[PATCH] for debug purpose only: add print to debug odd behavior.

[Francis Laniel <francis.laniel@amarulasolutions.com>]

Hi.


I am really sorry for the delay in answer.

Sadly, I am not able to send a v5 for the moment.
Indeed, I am still struggling with the same bug since a lot of time...
It happens in the Azure pipeline but also locally with test.py.

I am sure the bug is related to memory management as the setexpr test fails
because more memory is released than what expected (as shown by the debug
message printed in this patch).
Nonetheless, I am not able to say what is the root cause of it...
I think this is a side effect "somewhere", as commenting out the "loop_i=" in
the unit test for loop makes the tests pass.

Sometime ago, it happened with sandbox and sandbox_clang and with a recent
rebase it stopped happening on these boards but begins to occur on
sandbox_flattree.
I checked the behavior of the code related to loop and particularly what is done
by set_local_var_2021() with GDB and I did not find any uncorrect behavior.

I am sorry but I do not have a lot of other choices than asking for a bit of
help as I really want to tackle this but I am lacking ideas...
So, did such a bug already occur in U-Boot development process?
If so, what was the root cause and what was done to help finding it?


Best regards and thank you in advance as any help will be really appreciated.

---
 cmd/nvedit.c               |  7 ++++++-
 cmd/setexpr.c              |  4 ++++
 common/cli_hush_upstream.c | 28 ++++++++++++++++++++++++++++
 common/command.c           |  4 ++++
 include/cli_hush.h         |  4 ++++
 test/cmd/setexpr.c         |  8 ++++++++
 test/hush/loop.c           |  3 +++
 7 files changed, 57 insertions(+), 1 deletion(-)

diff --git a/cmd/nvedit.c b/cmd/nvedit.c
index 53e6b57b60..cf6ac9d7f2 100644
--- a/cmd/nvedit.c
+++ b/cmd/nvedit.c
@@ -40,6 +40,8 @@
 #include <linux/stddef.h>
 #include <asm/byteorder.h>
 #include <asm/io.h>
+#include <cli_hush.h>
+#include <test/ut.h>

 DECLARE_GLOBAL_DATA_PTR;

@@ -275,8 +277,9 @@ static int _do_env_set(int flag, int argc, char *const argv[], int env_flag)
 	 */
 	for (i = 2, len = 0; i < argc; ++i)
 		len += strlen(argv[i]) + 1;
-
+	debug_foo("\t\t\t%s: before malloc: ut_check_free(): %lu\n", __func__, ut_check_free());
 	value = malloc(len);
+// 	debug_foo("\t\t\t%s: after malloc: ut_check_free(): %lu\n", __func__, ut_check_free());
 	if (value == NULL) {
 		printf("## Can't malloc %d bytes\n", len);
 		return 1;
@@ -294,7 +297,9 @@ static int _do_env_set(int flag, int argc, char *const argv[], int env_flag)
 	e.key	= name;
 	e.data	= value;
 	hsearch_r(e, ENV_ENTER, &ep, &env_htab, env_flag);
+// 	debug_foo("\t\t\t%s: before free: ut_check_free(): %lu\n", __func__, ut_check_free());
 	free(value);
+	debug_foo("\t\t\t%s: after free: ut_check_free(): %lu\n", __func__, ut_check_free());
 	if (!ep) {
 		printf("## Error inserting \"%s\" variable, errno=%d\n",
 			name, errno);
diff --git a/cmd/setexpr.c b/cmd/setexpr.c
index 4d671e7ef1..a815dba4f7 100644
--- a/cmd/setexpr.c
+++ b/cmd/setexpr.c
@@ -18,6 +18,8 @@
 #include <mapmem.h>
 #include <linux/sizes.h>
 #include "printf.h"
+#include <cli_hush.h>
+#include <test/ut.h>

 #define MAX_STR_LEN 128

@@ -412,7 +414,9 @@ static int do_setexpr(struct cmd_tbl *cmdtp, int flag, int argc,
 	/* plain assignment: "setexpr name value" */
 	if (argc == 3) {
 		if (w == CMD_DATA_SIZE_STR) {
+			debug_foo("\t\t%s: before env_set: ut_check_free(): %lu\n", __func__, ut_check_free());
 			ret = env_set(argv[1], aval.sval);
+			debug_foo("\t\t%s: after env_set: ut_check_free(): %lu\n", __func__, ut_check_free());
 			free(aval.sval);
 		} else {
 			ret = env_set_hex(argv[1], aval.ival);
diff --git a/common/cli_hush_upstream.c b/common/cli_hush_upstream.c
index bf7e51f2f3..14c1b8dc19 100644
--- a/common/cli_hush_upstream.c
+++ b/common/cli_hush_upstream.c
@@ -381,6 +381,10 @@
 #endif
 #endif /* !__U_BOOT__ */

+#ifdef __U_BOOT__
+#include <test/ut.h>
+#endif
+
 /* So far, all bash compat is controlled by one config option */
 /* Separate defines document which part of code implements what */
 #define BASH_PATTERN_SUBST ENABLE_HUSH_BASH_COMPAT
@@ -9760,6 +9764,28 @@ static int redirect_and_varexp_helper(
 }
 #endif /* !__U_BOOT__ */

+bool foo = false;
+
+void set_debug_foo(void)
+{
+	foo = true;
+}
+
+void reset_debug_foo(void)
+{
+	foo = false;
+}
+
+void debug_foo(char *fmt, ...)
+{
+	if (foo) {
+		va_list args;
+		va_start(args, fmt);
+		vprintf(fmt, args);
+		va_end(args);
+	}
+}
+
 static NOINLINE int run_pipe(struct pipe *pi)
 {
 	static const char *const null_ptr = NULL;
@@ -10269,9 +10295,11 @@ static NOINLINE int run_pipe(struct pipe *pi)
 		next_infd = pipefds.rd;
 #else /* __U_BOOT__ */
 		/* Process the command */
+		debug_foo("%s: before cmd_process: ut_check_free(): %lu\n", __func__, ut_check_free());
 		rcode = cmd_process(G.do_repeat ? CMD_FLAG_REPEAT : 0,
 				    command->argc, command->argv,
 				    &(G.flag_repeat), NULL);
+		debug_foo("%s: after cmd_process: ut_check_free(): %lu\n", __func__, ut_check_free());

 		if (argv_expanded) {
 			/*
diff --git a/common/command.c b/common/command.c
index 41c91c6d8c..16660d3884 100644
--- a/common/command.c
+++ b/common/command.c
@@ -16,6 +16,8 @@
 #include <log.h>
 #include <asm/global_data.h>
 #include <linux/ctype.h>
+#include <cli_hush.h>
+#include <test/ut.h>

 DECLARE_GLOBAL_DATA_PTR;

@@ -577,7 +579,9 @@ static int cmd_call(struct cmd_tbl *cmdtp, int flag, int argc,
 {
 	int result;

+	debug_foo("\t%s: before cmd function: ut_check_free(): %lu\n", __func__, ut_check_free());
 	result = cmdtp->cmd_rep(cmdtp, flag, argc, argv, repeatable);
+	debug_foo("\t%s: after cmd function: ut_check_free(): %lu\n", __func__, ut_check_free());
 	if (result)
 		debug("Command failed, result=%d\n", result);
 	return result;
diff --git a/include/cli_hush.h b/include/cli_hush.h
index 6261aa1806..623b023fdd 100644
--- a/include/cli_hush.h
+++ b/include/cli_hush.h
@@ -12,6 +12,10 @@
 #define FLAG_REPARSING       (1 << 2)	  /* >=2nd pass */
 #define FLAG_CONT_ON_NEWLINE (1 << 3)	  /* continue when we see \n */

+void set_debug_foo(void);
+void reset_debug_foo(void);
+void debug_foo(char *fmt, ...);
+
 #if CONFIG_IS_ENABLED(HUSH_OLD_PARSER)
 extern int u_boot_hush_start(void);
 extern int parse_string_outer(const char *, int);
diff --git a/test/cmd/setexpr.c b/test/cmd/setexpr.c
index 0dc94f7e61..bf15c0a1b5 100644
--- a/test/cmd/setexpr.c
+++ b/test/cmd/setexpr.c
@@ -9,6 +9,7 @@
 #include <common.h>
 #include <console.h>
 #include <mapmem.h>
+#include <cli_hush.h>
 #include <dm/test.h>
 #include <test/suites.h>
 #include <test/ut.h>
@@ -304,12 +305,19 @@ static int setexpr_test_str(struct unit_test_state *uts)
 	ut_asserteq(1, run_command("setexpr.s fred 0", 0));
 	ut_assertok(ut_check_delta(start_mem));

+	ut_unsilence_console(uts);
+
 	ut_assertok(env_set("fred", "12345"));
 	start_mem = ut_check_free();
+
+	set_debug_foo();
 	ut_assertok(run_command("setexpr.s fred *0", 0));
+	reset_debug_foo();
 	ut_asserteq_str("hello", env_get("fred"));
 	ut_assertok(ut_check_delta(start_mem));

+	ut_silence_console(uts);
+
 	unmap_sysmem(buf);

 	return 0;
diff --git a/test/hush/loop.c b/test/hush/loop.c
index 8803dc6ae4..ab849f7fac 100644
--- a/test/hush/loop.c
+++ b/test/hush/loop.c
@@ -26,6 +26,9 @@ static int hush_test_for(struct unit_test_state *uts)

 	if (gd->flags & GD_FLG_HUSH_2021_PARSER) {
 		/* Reset local variable. */
+		/*
+		 * BUG Comment this below line out make the tests pass.
+		 */
 		ut_assertok(run_command("loop_i=", 0));
 	} else if (gd->flags & GD_FLG_HUSH_OLD_PARSER) {
 		puts("Beware: this test set local variable loop_i and it cannot be unset!");
--
2.25.1