[PATCH net-next 01/12] selftests/vsock: improve logging in vmtest.sh

Bobby Eshleman posted 12 patches 3 months, 2 weeks ago
There is a newer version of this series
[PATCH net-next 01/12] selftests/vsock: improve logging in vmtest.sh
Posted by Bobby Eshleman 3 months, 2 weeks ago
From: Bobby Eshleman <bobbyeshleman@meta.com>

Improve usability of logging functions. Remove the test name prefix from
logging functions so that logging calls can be made deeper into the call
stack without passing down the test name or setting some global. Teach
log function to accept a LOG_PREFIX variable to avoid unnecessary
argument shifting.

Remove log_setup() and instead use log_host(). The host/guest prefixes
are useful to show whether a failure happened on the guest or host side,
but "setup" doesn't really give additional useful information. Since all
log_setup() calls happen on the host, lets just use log_host() instead.

Signed-off-by: Bobby Eshleman <bobbyeshleman@meta.com>
---
Changes from previous series:
- do not use log levels, keep as on/off switch, after revising the other
  patch series the levels became unnecessary.
---
 tools/testing/selftests/vsock/vmtest.sh | 69 ++++++++++++++-------------------
 1 file changed, 29 insertions(+), 40 deletions(-)

diff --git a/tools/testing/selftests/vsock/vmtest.sh b/tools/testing/selftests/vsock/vmtest.sh
index edacebfc1632..561600814bef 100755
--- a/tools/testing/selftests/vsock/vmtest.sh
+++ b/tools/testing/selftests/vsock/vmtest.sh
@@ -271,60 +271,51 @@ EOF
 
 host_wait_for_listener() {
 	wait_for_listener "${TEST_HOST_PORT_LISTENER}" "${WAIT_PERIOD}" "${WAIT_PERIOD_MAX}"
-}
-
-__log_stdin() {
-	cat | awk '{ printf "%s:\t%s\n","'"${prefix}"'", $0 }'
-}
 
-__log_args() {
-	echo "$*" | awk '{ printf "%s:\t%s\n","'"${prefix}"'", $0 }'
 }
 
 log() {
-	local prefix="$1"
+	local redirect
+	local prefix
 
-	shift
-	local redirect=
 	if [[ ${VERBOSE} -eq 0 ]]; then
 		redirect=/dev/null
 	else
 		redirect=/dev/stdout
 	fi
 
+	prefix="${LOG_PREFIX:-}"
+
 	if [[ "$#" -eq 0 ]]; then
-		__log_stdin | tee -a "${LOG}" > ${redirect}
+		if [[ -n "${prefix}" ]]; then
+			cat | awk -v prefix="${prefix}" '{printf "%s: %s\n", prefix, $0}'
+		else
+			cat
+		fi
 	else
-		__log_args "$@" | tee -a "${LOG}" > ${redirect}
-	fi
-}
-
-log_setup() {
-	log "setup" "$@"
+		if [[ -n "${prefix}" ]]; then
+			echo "${prefix}: " "$@"
+		else
+			echo "$@"
+		fi
+	fi | tee -a "${LOG}" > ${redirect}
 }
 
 log_host() {
-	local testname=$1
-
-	shift
-	log "test:${testname}:host" "$@"
+	LOG_PREFIX=host log $@
 }
 
 log_guest() {
-	local testname=$1
-
-	shift
-	log "test:${testname}:guest" "$@"
+	LOG_PREFIX=guest log $@
 }
 
 test_vm_server_host_client() {
-	local testname="${FUNCNAME[0]#test_}"
 
 	vm_ssh -- "${VSOCK_TEST}" \
 		--mode=server \
 		--control-port="${TEST_GUEST_PORT}" \
 		--peer-cid=2 \
-		2>&1 | log_guest "${testname}" &
+		2>&1 | log_guest &
 
 	vm_wait_for_listener "${TEST_GUEST_PORT}"
 
@@ -332,18 +323,17 @@ test_vm_server_host_client() {
 		--mode=client \
 		--control-host=127.0.0.1 \
 		--peer-cid="${VSOCK_CID}" \
-		--control-port="${TEST_HOST_PORT}" 2>&1 | log_host "${testname}"
+		--control-port="${TEST_HOST_PORT}" 2>&1 | log_host
 
 	return $?
 }
 
 test_vm_client_host_server() {
-	local testname="${FUNCNAME[0]#test_}"
 
 	${VSOCK_TEST} \
 		--mode "server" \
 		--control-port "${TEST_HOST_PORT_LISTENER}" \
-		--peer-cid "${VSOCK_CID}" 2>&1 | log_host "${testname}" &
+		--peer-cid "${VSOCK_CID}" 2>&1 | log_host &
 
 	host_wait_for_listener
 
@@ -351,19 +341,18 @@ test_vm_client_host_server() {
 		--mode=client \
 		--control-host=10.0.2.2 \
 		--peer-cid=2 \
-		--control-port="${TEST_HOST_PORT_LISTENER}" 2>&1 | log_guest "${testname}"
+		--control-port="${TEST_HOST_PORT_LISTENER}" 2>&1 | log_guest
 
 	return $?
 }
 
 test_vm_loopback() {
-	local testname="${FUNCNAME[0]#test_}"
 	local port=60000 # non-forwarded local port
 
 	vm_ssh -- "${VSOCK_TEST}" \
 		--mode=server \
 		--control-port="${port}" \
-		--peer-cid=1 2>&1 | log_guest "${testname}" &
+		--peer-cid=1 2>&1 | log_guest &
 
 	vm_wait_for_listener "${port}"
 
@@ -371,7 +360,7 @@ test_vm_loopback() {
 		--mode=client \
 		--control-host="127.0.0.1" \
 		--control-port="${port}" \
-		--peer-cid=1 2>&1 | log_guest "${testname}"
+		--peer-cid=1 2>&1 | log_guest
 
 	return $?
 }
@@ -399,25 +388,25 @@ run_test() {
 
 	host_oops_cnt_after=$(dmesg | grep -i 'Oops' | wc -l)
 	if [[ ${host_oops_cnt_after} -gt ${host_oops_cnt_before} ]]; then
-		echo "FAIL: kernel oops detected on host" | log_host "${name}"
+		echo "FAIL: kernel oops detected on host" | log_host
 		rc=$KSFT_FAIL
 	fi
 
 	host_warn_cnt_after=$(dmesg --level=warn | wc -l)
 	if [[ ${host_warn_cnt_after} -gt ${host_warn_cnt_before} ]]; then
-		echo "FAIL: kernel warning detected on host" | log_host "${name}"
+		echo "FAIL: kernel warning detected on host" | log_host
 		rc=$KSFT_FAIL
 	fi
 
 	vm_oops_cnt_after=$(vm_ssh -- dmesg | grep -i 'Oops' | wc -l)
 	if [[ ${vm_oops_cnt_after} -gt ${vm_oops_cnt_before} ]]; then
-		echo "FAIL: kernel oops detected on vm" | log_host "${name}"
+		echo "FAIL: kernel oops detected on vm" | log_host
 		rc=$KSFT_FAIL
 	fi
 
 	vm_warn_cnt_after=$(vm_ssh -- dmesg --level=warn | wc -l)
 	if [[ ${vm_warn_cnt_after} -gt ${vm_warn_cnt_before} ]]; then
-		echo "FAIL: kernel warning detected on vm" | log_host "${name}"
+		echo "FAIL: kernel warning detected on vm" | log_host
 		rc=$KSFT_FAIL
 	fi
 
@@ -452,10 +441,10 @@ handle_build
 
 echo "1..${#ARGS[@]}"
 
-log_setup "Booting up VM"
+log_host "Booting up VM"
 vm_start
 vm_wait_for_ssh
-log_setup "VM booted up"
+log_host "VM booted up"
 
 cnt_pass=0
 cnt_fail=0

-- 
2.47.3
Re: [PATCH net-next 01/12] selftests/vsock: improve logging in vmtest.sh
Posted by Simon Horman 3 months, 2 weeks ago
On Wed, Oct 22, 2025 at 06:00:05PM -0700, Bobby Eshleman wrote:
> From: Bobby Eshleman <bobbyeshleman@meta.com>
> 
> Improve usability of logging functions. Remove the test name prefix from
> logging functions so that logging calls can be made deeper into the call
> stack without passing down the test name or setting some global. Teach
> log function to accept a LOG_PREFIX variable to avoid unnecessary
> argument shifting.
> 
> Remove log_setup() and instead use log_host(). The host/guest prefixes
> are useful to show whether a failure happened on the guest or host side,
> but "setup" doesn't really give additional useful information. Since all
> log_setup() calls happen on the host, lets just use log_host() instead.
> 
> Signed-off-by: Bobby Eshleman <bobbyeshleman@meta.com>

...

>  log() {
> -	local prefix="$1"
> +	local redirect
> +	local prefix
>  
> -	shift
> -	local redirect=
>  	if [[ ${VERBOSE} -eq 0 ]]; then
>  		redirect=/dev/null
>  	else
>  		redirect=/dev/stdout
>  	fi
>  
> +	prefix="${LOG_PREFIX:-}"
> +
>  	if [[ "$#" -eq 0 ]]; then
> -		__log_stdin | tee -a "${LOG}" > ${redirect}
> +		if [[ -n "${prefix}" ]]; then
> +			cat | awk -v prefix="${prefix}" '{printf "%s: %s\n", prefix, $0}'

FIWIIW, I would drop cat from this line.

> +		else
> +			cat
> +		fi
>  	else
> -		__log_args "$@" | tee -a "${LOG}" > ${redirect}
> -	fi
> -}
> -
> -log_setup() {
> -	log "setup" "$@"
> +		if [[ -n "${prefix}" ]]; then
> +			echo "${prefix}: " "$@"
> +		else
> +			echo "$@"
> +		fi
> +	fi | tee -a "${LOG}" > ${redirect}
>  }
>  
>  log_host() {
> -	local testname=$1
> -
> -	shift
> -	log "test:${testname}:host" "$@"
> +	LOG_PREFIX=host log $@

shellcheck suggests keeping the quoting of $@.
This seems reasonable to me. Although in practice I don't think
it will change the behaviour of this script.

>  }
>  log_host
>  log_guest() {
> -	local testname=$1
> -
> -	shift
> -	log "test:${testname}:guest" "$@"
> +	LOG_PREFIX=guest log $@

shellcheck also points out that log_guest is never passed
arguments, so $@ can be dropped. If you prefer to keep
it then, as per log_host, it seems reasonable for it to be quoted.

>  }

...
Re: [PATCH net-next 01/12] selftests/vsock: improve logging in vmtest.sh
Posted by Bobby Eshleman 3 months, 2 weeks ago
On Mon, Oct 27, 2025 at 04:45:27PM +0000, Simon Horman wrote:
> >  log() {
> > -	local prefix="$1"
> > +	local redirect
> > +	local prefix
> >  
> > -	shift
> > -	local redirect=
> >  	if [[ ${VERBOSE} -eq 0 ]]; then
> >  		redirect=/dev/null
> >  	else
> >  		redirect=/dev/stdout
> >  	fi
> >  
> > +	prefix="${LOG_PREFIX:-}"
> > +
> >  	if [[ "$#" -eq 0 ]]; then
> > -		__log_stdin | tee -a "${LOG}" > ${redirect}
> > +		if [[ -n "${prefix}" ]]; then
> > +			cat | awk -v prefix="${prefix}" '{printf "%s: %s\n", prefix, $0}'
> 
> FIWIIW, I would drop cat from this line.
> 

sgtm!

> > +		else
> > +			cat
> > +		fi
> >  	else
> > -		__log_args "$@" | tee -a "${LOG}" > ${redirect}
> > -	fi
> > -}
> > -
> > -log_setup() {
> > -	log "setup" "$@"
> > +		if [[ -n "${prefix}" ]]; then
> > +			echo "${prefix}: " "$@"
> > +		else
> > +			echo "$@"
> > +		fi
> > +	fi | tee -a "${LOG}" > ${redirect}
> >  }
> >  
> >  log_host() {
> > -	local testname=$1
> > -
> > -	shift
> > -	log "test:${testname}:host" "$@"
> > +	LOG_PREFIX=host log $@
> 
> shellcheck suggests keeping the quoting of $@.
> This seems reasonable to me. Although in practice I don't think
> it will change the behaviour of this script.
> 

Ah right, makes sense to me.

> >  }
> >  log_host
> >  log_guest() {
> > -	local testname=$1
> > -
> > -	shift
> > -	log "test:${testname}:guest" "$@"
> > +	LOG_PREFIX=guest log $@
> 
> shellcheck also points out that log_guest is never passed
> arguments, so $@ can be dropped. If you prefer to keep
> it then, as per log_host, it seems reasonable for it to be quoted.
> 

Quoting it sounds best to me, in keeping with log_host().


Thanks,
Bobby