[PATCH] test: Update lib/term for clearer output when DEBUG is enabled

[PATCH] test: Update lib/term for clearer output when DEBUG is enabled

[Yumei Huang]

When running tests with DEBUG=1, we used to get some
"DEBUG:DEBUG:DEBUG:" in logs, which is not very helpful for
debugging.

With this patch, the log would show the steps like below:

    DEBUG: g1tools  ip jq dhclient socat cat
    DEBUG: htools   ip jq
    DEBUG:
    DEBUG: set      MAP_HOST4 192.0.2.1
    DEBUG: set      MAP_HOST6 2001:db8:9a55::1

Suggested-by: David Gibson <david@gibson.dropbear.id.au>
Signed-off-by: Yumei Huang <yuhuang@redhat.com>
---
 test/lib/term | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/test/lib/term b/test/lib/term
index 089364c..6400746 100755
--- a/test/lib/term
+++ b/test/lib/term
@@ -32,29 +32,29 @@ PR_DELAY_INIT=100 # ms
 # $@:	Message to print
 info() {
 	tmux select-pane -t ${PANE_INFO}
-	printf "${@}\n" >> $STATEBASE/log_pipe
-	printf "${@}\n" >> "${LOGFILE}"
+	printf "${*}\n" >> $STATEBASE/log_pipe
+	printf "${*}\n" >> "${LOGFILE}"
 }
 
 # info_n() - Highlight, print message to pane and to log file without newline
 # $@:	Message to print
 info_n() {
 	tmux select-pane -t ${PANE_INFO}
-	printf "${@}" >> $STATEBASE/log_pipe
-	printf "${@}" >> "${LOGFILE}"
+	printf "${*}" >> $STATEBASE/log_pipe
+	printf "${*}" >> "${LOGFILE}"
 }
 
 # info_nolog() - Highlight test log pane, print message to it
 # $@:	Message to print
 info_nolog() {
 	tmux select-pane -t ${PANE_INFO}
-	printf "${@}\n" >> $STATEBASE/log_pipe
+	printf "${*}\n" >> $STATEBASE/log_pipe
 }
 
 # info_nolog() - Print message to log file
 # $@:	Message to print
 log() {
-	printf "${@}\n" >> "${LOGFILE}"
+	printf "${*}\n" >> "${LOGFILE}"
 }
 
 # info_nolog_n() - Send message to pane without highlighting it, without newline
@@ -363,8 +363,8 @@ status_test_start() {
 info_check() {
 	switch_pane ${PANE_INFO}
 
-	printf "${PR_YELLOW}?${PR_NC} ${@}" >> $STATEBASE/log_pipe
-	printf "? ${@}" >> "${LOGFILE}"
+	printf "${PR_YELLOW}?${PR_NC} ${*}" >> $STATEBASE/log_pipe
+	printf "? ${*}" >> "${LOGFILE}"
 }
 
 # info_check_passed() - Display and log a new line when a check passes
-- 
2.47.0

Re: [PATCH] test: Update lib/term for clearer output when DEBUG is enabled

[Stefano Brivio]

On Fri, 26 Sep 2025 14:15:53 +0800
Yumei Huang <yuhuang@redhat.com> wrote:

> When running tests with DEBUG=1, we used to get some
> "DEBUG:DEBUG:DEBUG:" in logs, which is not very helpful for
> debugging.

I didn't review this yet, but thanks a lot for fixing it this. I deeply
hated this issue and yet I never found a moment to look into it...

-- 
Stefano

Re: [PATCH] test: Update lib/term for clearer output when DEBUG is enabled

[David Gibson]

[-- Attachment #1: Type: text/plain, Size: 3011 bytes --]

On Fri, Sep 26, 2025 at 02:15:53PM +0800, Yumei Huang wrote:
> When running tests with DEBUG=1, we used to get some
> "DEBUG:DEBUG:DEBUG:" in logs, which is not very helpful for
> debugging.
> 
> With this patch, the log would show the steps like below:
> 
>     DEBUG: g1tools  ip jq dhclient socat cat
>     DEBUG: htools   ip jq
>     DEBUG:
>     DEBUG: set      MAP_HOST4 192.0.2.1
>     DEBUG: set      MAP_HOST6 2001:db8:9a55::1
> 
> Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> Signed-off-by: Yumei Huang <yuhuang@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

Some extra background that might be useful in the commit message:


The problem here is that "${@}" is magic and expands to multiple
arguments, even though it's quoted.  That means instead of the whole
message going into a single string, the "DEBUG:" becomes the format
string and the rest goes into unused parameters.


I'm pretty sure these messages worked once, I'm not sure exactly when
and how they broke.

> ---
>  test/lib/term | 16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)
> 
> diff --git a/test/lib/term b/test/lib/term
> index 089364c..6400746 100755
> --- a/test/lib/term
> +++ b/test/lib/term
> @@ -32,29 +32,29 @@ PR_DELAY_INIT=100 # ms
>  # $@:	Message to print
>  info() {
>  	tmux select-pane -t ${PANE_INFO}
> -	printf "${@}\n" >> $STATEBASE/log_pipe
> -	printf "${@}\n" >> "${LOGFILE}"
> +	printf "${*}\n" >> $STATEBASE/log_pipe
> +	printf "${*}\n" >> "${LOGFILE}"
>  }
>  
>  # info_n() - Highlight, print message to pane and to log file without newline
>  # $@:	Message to print
>  info_n() {
>  	tmux select-pane -t ${PANE_INFO}
> -	printf "${@}" >> $STATEBASE/log_pipe
> -	printf "${@}" >> "${LOGFILE}"
> +	printf "${*}" >> $STATEBASE/log_pipe
> +	printf "${*}" >> "${LOGFILE}"
>  }
>  
>  # info_nolog() - Highlight test log pane, print message to it
>  # $@:	Message to print
>  info_nolog() {
>  	tmux select-pane -t ${PANE_INFO}
> -	printf "${@}\n" >> $STATEBASE/log_pipe
> +	printf "${*}\n" >> $STATEBASE/log_pipe
>  }
>  
>  # info_nolog() - Print message to log file
>  # $@:	Message to print
>  log() {
> -	printf "${@}\n" >> "${LOGFILE}"
> +	printf "${*}\n" >> "${LOGFILE}"
>  }
>  
>  # info_nolog_n() - Send message to pane without highlighting it, without newline
> @@ -363,8 +363,8 @@ status_test_start() {
>  info_check() {
>  	switch_pane ${PANE_INFO}
>  
> -	printf "${PR_YELLOW}?${PR_NC} ${@}" >> $STATEBASE/log_pipe
> -	printf "? ${@}" >> "${LOGFILE}"
> +	printf "${PR_YELLOW}?${PR_NC} ${*}" >> $STATEBASE/log_pipe
> +	printf "? ${*}" >> "${LOGFILE}"
>  }
>  
>  # info_check_passed() - Display and log a new line when a check passes
> -- 
> 2.47.0
> 

-- 
David Gibson (he or they)	| I'll have my music baroque, and my code
david AT gibson.dropbear.id.au	| minimalist, thank you, not the other way
				| around.
http://www.ozlabs.org/~dgibson

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH] test: Update lib/term for clearer output when DEBUG is enabled

[Stefano Brivio]

On Fri, 26 Sep 2025 16:23:48 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> On Fri, Sep 26, 2025 at 02:15:53PM +0800, Yumei Huang wrote:
> > When running tests with DEBUG=1, we used to get some
> > "DEBUG:DEBUG:DEBUG:" in logs, which is not very helpful for
> > debugging.
> > 
> > With this patch, the log would show the steps like below:
> > 
> >     DEBUG: g1tools  ip jq dhclient socat cat
> >     DEBUG: htools   ip jq
> >     DEBUG:
> >     DEBUG: set      MAP_HOST4 192.0.2.1
> >     DEBUG: set      MAP_HOST6 2001:db8:9a55::1
> > 
> > Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> > Signed-off-by: Yumei Huang <yuhuang@redhat.com>  
> 
> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
> 
> Some extra background that might be useful in the commit message:
> 
> 
> The problem here is that "${@}" is magic and expands to multiple
> arguments, even though it's quoted.  That means instead of the whole
> message going into a single string, the "DEBUG:" becomes the format
> string and the rest goes into unused parameters.

Applied, with this addition to the commit message.

-- 
Stefano

Re: [PATCH] test: Update lib/term for clearer output when DEBUG is enabled

[Yumei Huang]

On Fri, Sep 26, 2025 at 8:38 PM Stefano Brivio <sbrivio@redhat.com> wrote:
>
> On Fri, 26 Sep 2025 16:23:48 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
>
> > On Fri, Sep 26, 2025 at 02:15:53PM +0800, Yumei Huang wrote:
> > > When running tests with DEBUG=1, we used to get some
> > > "DEBUG:DEBUG:DEBUG:" in logs, which is not very helpful for
> > > debugging.
> > >
> > > With this patch, the log would show the steps like below:
> > >
> > >     DEBUG: g1tools  ip jq dhclient socat cat
> > >     DEBUG: htools   ip jq
> > >     DEBUG:
> > >     DEBUG: set      MAP_HOST4 192.0.2.1
> > >     DEBUG: set      MAP_HOST6 2001:db8:9a55::1
> > >
> > > Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> > > Signed-off-by: Yumei Huang <yuhuang@redhat.com>
> >
> > Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
> >
> > Some extra background that might be useful in the commit message:
> >
> >
> > The problem here is that "${@}" is magic and expands to multiple
> > arguments, even though it's quoted.  That means instead of the whole
> > message going into a single string, the "DEBUG:" becomes the format
> > string and the rest goes into unused parameters.
>
> Applied, with this addition to the commit message.

Thank you for helping merge this so quickly.

I just found this patch introduced a regression issue to some tests.
Will fix it with a new patch. Sorry about that.

>
> --
> Stefano
>


-- 
Thanks,

Yumei Huang