test/common: stop relying on bash $SECONDS in check_dmesg()

test/common: stop relying on bash $SECONDS in check_dmesg()

[marc.herbert]

As requested, this is the broken-down, first part of
  https://lore.kernel.org/linux-cxl/20250611235256.3866724-1-marc.herbert@linux.intel.com/
  test: fail on unexpected kernel error & warning, not just "Call Trace"

I will resubmit the rest after the review of this first part is
completed. The different parts are logically separate (different
"features") but they are interleaved in the same function and I don't
really have the time to fix one git conflict per review comment. 

While it is a requirement to catch warnings and errors later, the
better accuracy provided by this first part is useful alone. If you
are interested in what's next, just look at the bigger patch above.
You don't have to!

[ndctl PATCH 1/3] test/common: add missing quotes

[marc.herbert]

From: Marc Herbert <marc.herbert@linux.intel.com>

This makes shellcheck much happier and its output readable and usable.

Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>
---
 test/common | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/test/common b/test/common
index 75ff1a6e12be..2d8422f26436 100644
--- a/test/common
+++ b/test/common
@@ -4,7 +4,7 @@
 # Global variables
 
 # NDCTL
-if [ -z $NDCTL ]; then
+if [ -z "$NDCTL" ]; then
 	if [ -f "../ndctl/ndctl" ] && [ -x "../ndctl/ndctl" ]; then
 		export NDCTL=../ndctl/ndctl
 	elif [ -f "./ndctl/ndctl" ] && [ -x "./ndctl/ndctl" ]; then
@@ -16,7 +16,7 @@ if [ -z $NDCTL ]; then
 fi
 
 # DAXCTL
-if [ -z $DAXCTL ]; then
+if [ -z "$DAXCTL" ]; then
 	if [ -f "../daxctl/daxctl" ] && [ -x "../daxctl/daxctl" ]; then
 		export DAXCTL=../daxctl/daxctl
 	elif [ -f "./daxctl/daxctl" ] && [ -x "./daxctl/daxctl" ]; then
@@ -28,7 +28,7 @@ if [ -z $DAXCTL ]; then
 fi
 
 # CXL
-if [ -z $CXL ]; then
+if [ -z "$CXL" ]; then
 	if [ -f "../cxl/cxl" ] && [ -x "../cxl/cxl" ]; then
 		export CXL=../cxl/cxl
 	elif [ -f "./cxl/cxl" ] && [ -x "./cxl/cxl" ]; then
@@ -39,7 +39,7 @@ if [ -z $CXL ]; then
 	fi
 fi
 
-if [ -z $TEST_PATH ]; then
+if [ -z "$TEST_PATH" ]; then
 	export TEST_PATH=.
 fi
 
@@ -103,7 +103,7 @@ check_min_kver()
 #
 do_skip()
 {
-	echo kernel $(uname -r): $1
+	echo kernel "$(uname -r)": "$1"
 	exit 77
 }
 
@@ -147,7 +147,7 @@ check_dmesg()
 	# validate no WARN or lockdep report during the run
 	sleep 1
 	log=$(journalctl -r -k --since "-$((SECONDS+1))s")
-	grep -q "Call Trace" <<< $log && err $1
+	grep -q "Call Trace" <<< "$log" && err "$1"
 	true
 }
 
-- 
2.50.1

Re: [ndctl PATCH 1/3] test/common: add missing quotes

[Dave Jiang]

On 7/24/25 3:00 PM, marc.herbert@linux.intel.com wrote:
> From: Marc Herbert <marc.herbert@linux.intel.com>
> 
> This makes shellcheck much happier and its output readable and usable.

Probably should mention what exactly you are changing.

> 
> Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>

Reviewed-by: Dave Jiang <dave.jiang@intel.com>
> ---
>  test/common | 12 ++++++------
>  1 file changed, 6 insertions(+), 6 deletions(-)
> 
> diff --git a/test/common b/test/common
> index 75ff1a6e12be..2d8422f26436 100644
> --- a/test/common
> +++ b/test/common
> @@ -4,7 +4,7 @@
>  # Global variables
>  
>  # NDCTL
> -if [ -z $NDCTL ]; then
> +if [ -z "$NDCTL" ]; then
>  	if [ -f "../ndctl/ndctl" ] && [ -x "../ndctl/ndctl" ]; then
>  		export NDCTL=../ndctl/ndctl
>  	elif [ -f "./ndctl/ndctl" ] && [ -x "./ndctl/ndctl" ]; then
> @@ -16,7 +16,7 @@ if [ -z $NDCTL ]; then
>  fi
>  
>  # DAXCTL
> -if [ -z $DAXCTL ]; then
> +if [ -z "$DAXCTL" ]; then
>  	if [ -f "../daxctl/daxctl" ] && [ -x "../daxctl/daxctl" ]; then
>  		export DAXCTL=../daxctl/daxctl
>  	elif [ -f "./daxctl/daxctl" ] && [ -x "./daxctl/daxctl" ]; then
> @@ -28,7 +28,7 @@ if [ -z $DAXCTL ]; then
>  fi
>  
>  # CXL
> -if [ -z $CXL ]; then
> +if [ -z "$CXL" ]; then
>  	if [ -f "../cxl/cxl" ] && [ -x "../cxl/cxl" ]; then
>  		export CXL=../cxl/cxl
>  	elif [ -f "./cxl/cxl" ] && [ -x "./cxl/cxl" ]; then
> @@ -39,7 +39,7 @@ if [ -z $CXL ]; then
>  	fi
>  fi
>  
> -if [ -z $TEST_PATH ]; then
> +if [ -z "$TEST_PATH" ]; then
>  	export TEST_PATH=.
>  fi
>  
> @@ -103,7 +103,7 @@ check_min_kver()
>  #
>  do_skip()
>  {
> -	echo kernel $(uname -r): $1
> +	echo kernel "$(uname -r)": "$1"
>  	exit 77
>  }
>  
> @@ -147,7 +147,7 @@ check_dmesg()
>  	# validate no WARN or lockdep report during the run
>  	sleep 1
>  	log=$(journalctl -r -k --since "-$((SECONDS+1))s")
> -	grep -q "Call Trace" <<< $log && err $1
> +	grep -q "Call Trace" <<< "$log" && err "$1"
>  	true
>  }
>  

Re: [ndctl PATCH 1/3] test/common: add missing quotes

[Alison Schofield]

On Thu, Jul 24, 2025 at 10:00:44PM +0000, marc.herbert@linux.intel.com wrote:
> From: Marc Herbert <marc.herbert@linux.intel.com>
> 
> This makes shellcheck much happier and its output readable and usable.
> 
> Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>

Thanks!
Applied to https://github.com/pmem/ndctl/commits/pending/
with [alison: edit commit message and log]

> ---
>  test/common | 12 ++++++------
>  1 file changed, 6 insertions(+), 6 deletions(-)
> 
> diff --git a/test/common b/test/common
> index 75ff1a6e12be..2d8422f26436 100644
> --- a/test/common
> +++ b/test/common
> @@ -4,7 +4,7 @@
>  # Global variables
>  
>  # NDCTL
> -if [ -z $NDCTL ]; then
> +if [ -z "$NDCTL" ]; then
>  	if [ -f "../ndctl/ndctl" ] && [ -x "../ndctl/ndctl" ]; then
>  		export NDCTL=../ndctl/ndctl
>  	elif [ -f "./ndctl/ndctl" ] && [ -x "./ndctl/ndctl" ]; then
> @@ -16,7 +16,7 @@ if [ -z $NDCTL ]; then
>  fi
>  
>  # DAXCTL
> -if [ -z $DAXCTL ]; then
> +if [ -z "$DAXCTL" ]; then
>  	if [ -f "../daxctl/daxctl" ] && [ -x "../daxctl/daxctl" ]; then
>  		export DAXCTL=../daxctl/daxctl
>  	elif [ -f "./daxctl/daxctl" ] && [ -x "./daxctl/daxctl" ]; then
> @@ -28,7 +28,7 @@ if [ -z $DAXCTL ]; then
>  fi
>  
>  # CXL
> -if [ -z $CXL ]; then
> +if [ -z "$CXL" ]; then
>  	if [ -f "../cxl/cxl" ] && [ -x "../cxl/cxl" ]; then
>  		export CXL=../cxl/cxl
>  	elif [ -f "./cxl/cxl" ] && [ -x "./cxl/cxl" ]; then
> @@ -39,7 +39,7 @@ if [ -z $CXL ]; then
>  	fi
>  fi
>  
> -if [ -z $TEST_PATH ]; then
> +if [ -z "$TEST_PATH" ]; then
>  	export TEST_PATH=.
>  fi
>  
> @@ -103,7 +103,7 @@ check_min_kver()
>  #
>  do_skip()
>  {
> -	echo kernel $(uname -r): $1
> +	echo kernel "$(uname -r)": "$1"
>  	exit 77
>  }
>  
> @@ -147,7 +147,7 @@ check_dmesg()
>  	# validate no WARN or lockdep report during the run
>  	sleep 1
>  	log=$(journalctl -r -k --since "-$((SECONDS+1))s")
> -	grep -q "Call Trace" <<< $log && err $1
> +	grep -q "Call Trace" <<< "$log" && err "$1"
>  	true
>  }
>  
> -- 
> 2.50.1
> 

[ndctl PATCH 2/3] test/common: move err() function at the top

[marc.herbert]

From: Marc Herbert <marc.herbert@linux.intel.com>

move err() function at the top so we can fail early. err() does not have
any dependency so it can be first.

Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>
---
 test/common | 25 ++++++++++++++-----------
 1 file changed, 14 insertions(+), 11 deletions(-)

diff --git a/test/common b/test/common
index 2d8422f26436..2d076402ef7c 100644
--- a/test/common
+++ b/test/common
@@ -1,6 +1,20 @@
 # SPDX-License-Identifier: GPL-2.0
 # Copyright (C) 2018, FUJITSU LIMITED. All rights reserved.
 
+# err
+# $1: line number which error detected
+# $2: cleanup function (optional)
+#
+
+test_basename=$(basename "$0")
+
+err()
+{
+	echo test/"$test_basename": failed at line "$1"
+	[ -n "$2" ] && "$2"
+	exit "$rc"
+}
+
 # Global variables
 
 # NDCTL
@@ -53,17 +67,6 @@ E820_BUS="e820"
 
 # Functions
 
-# err
-# $1: line number which error detected
-# $2: cleanup function (optional)
-#
-err()
-{
-	echo test/$(basename $0): failed at line $1
-	[ -n "$2" ] && "$2"
-	exit $rc
-}
-
 reset()
 {
 	$NDCTL disable-region -b $NFIT_TEST_BUS0 all
-- 
2.50.1

Re: [ndctl PATCH 2/3] test/common: move err() function at the top

[Dave Jiang]

On 7/24/25 3:00 PM, marc.herbert@linux.intel.com wrote:
> From: Marc Herbert <marc.herbert@linux.intel.com>
> 
> move err() function at the top so we can fail early. err() does not have
> any dependency so it can be first.
> 
> Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>
Reviewed-by: Dave Jiang <dave.jiang@intel.com>
> ---
>  test/common | 25 ++++++++++++++-----------
>  1 file changed, 14 insertions(+), 11 deletions(-)
> 
> diff --git a/test/common b/test/common
> index 2d8422f26436..2d076402ef7c 100644
> --- a/test/common
> +++ b/test/common
> @@ -1,6 +1,20 @@
>  # SPDX-License-Identifier: GPL-2.0
>  # Copyright (C) 2018, FUJITSU LIMITED. All rights reserved.
>  
> +# err
> +# $1: line number which error detected
> +# $2: cleanup function (optional)
> +#
> +
> +test_basename=$(basename "$0")
> +
> +err()
> +{
> +	echo test/"$test_basename": failed at line "$1"
> +	[ -n "$2" ] && "$2"
> +	exit "$rc"
> +}
> +
>  # Global variables
>  
>  # NDCTL
> @@ -53,17 +67,6 @@ E820_BUS="e820"
>  
>  # Functions
>  
> -# err
> -# $1: line number which error detected
> -# $2: cleanup function (optional)
> -#
> -err()
> -{
> -	echo test/$(basename $0): failed at line $1
> -	[ -n "$2" ] && "$2"
> -	exit $rc
> -}
> -
>  reset()
>  {
>  	$NDCTL disable-region -b $NFIT_TEST_BUS0 all

Re: [ndctl PATCH 2/3] test/common: move err() function at the top

[Alison Schofield]

On Thu, Jul 24, 2025 at 10:00:45PM +0000, marc.herbert@linux.intel.com wrote:
> From: Marc Herbert <marc.herbert@linux.intel.com>
> 
> move err() function at the top so we can fail early. err() does not have
> any dependency so it can be first.
> 
> Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>

Thanks!
Applied to https://github.com/pmem/ndctl/commits/pending/
with [alison: edit commit message and log]

> ---
>  test/common | 25 ++++++++++++++-----------
>  1 file changed, 14 insertions(+), 11 deletions(-)
> 
> diff --git a/test/common b/test/common
> index 2d8422f26436..2d076402ef7c 100644
> --- a/test/common
> +++ b/test/common
> @@ -1,6 +1,20 @@
>  # SPDX-License-Identifier: GPL-2.0
>  # Copyright (C) 2018, FUJITSU LIMITED. All rights reserved.
>  
> +# err
> +# $1: line number which error detected
> +# $2: cleanup function (optional)
> +#
> +
> +test_basename=$(basename "$0")
> +
> +err()
> +{
> +	echo test/"$test_basename": failed at line "$1"
> +	[ -n "$2" ] && "$2"
> +	exit "$rc"
> +}
> +
>  # Global variables
>  
>  # NDCTL
> @@ -53,17 +67,6 @@ E820_BUS="e820"
>  
>  # Functions
>  
> -# err
> -# $1: line number which error detected
> -# $2: cleanup function (optional)
> -#
> -err()
> -{
> -	echo test/$(basename $0): failed at line $1
> -	[ -n "$2" ] && "$2"
> -	exit $rc
> -}
> -
>  reset()
>  {
>  	$NDCTL disable-region -b $NFIT_TEST_BUS0 all
> -- 
> 2.50.1
> 

[ndctl PATCH 3/3] test/common: stop relying on bash $SECONDS in check_dmesg()

[marc.herbert]

From: Marc Herbert <marc.herbert@linux.intel.com>

Stop relying on the imprecise bash $SECONDS variable as a test start
timestamp when scanning the logs for issues.

$SECONDS was convenient because it came "for free" and did not require
any time_init(). But it was not fine-grained enough and its rounding
process is not even documented. Keep using $SECONDS in log messages
where it is easy to use and more user-friendly than bare timestamps, but
switch the critical journalctl scan to a new, absolute NDTEST_START
timestamp initialized when test/common is sourced. Use a SECONDS-based,
rough sanity check in time_init() to make sure test/common is always
sourced early.

Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>
---
 test/common | 52 ++++++++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 50 insertions(+), 2 deletions(-)

diff --git a/test/common b/test/common
index 2d076402ef7c..0214c6aaed5f 100644
--- a/test/common
+++ b/test/common
@@ -15,6 +15,25 @@ err()
 	exit "$rc"
 }
 
+# Initialize the NDTEST_START timestamp used to scan the logs.
+# Insert an anchor/bookmark in the logs to quickly locate the start of any test.
+time_init()
+{
+	# Refuse to run if anything lasted for too long before this point
+	# because that would make NDTEST_START incorrect.
+	test "$SECONDS" -le 1 || err 'test/common must be included first!'
+
+	NDTEST_START=$(LC_TIME=C date '+%F %T.%3N')
+
+	# Log anchor, especially useful when running tests back to back
+	printf "<5>%s@%ds: sourcing test/common: NDTEST_START=%s\n" \
+		"$test_basename" "$SECONDS" "$NDTEST_START" > /dev/kmsg
+
+	# Default value, can be overridden by the environment
+	: "${NDTEST_LOG_DBG:=false}"
+}
+time_init
+
 # Global variables
 
 # NDCTL
@@ -147,11 +166,40 @@ json2var()
 # $1: line number where this is called
 check_dmesg()
 {
+	if "$NDTEST_LOG_DBG"; then
+		# Keep a record of which log lines we scanned
+		journalctl -q -b --since "$NDTEST_START" \
+			-o short-precise > journal-"$(basename "$0")".log
+	fi
+	# After enabling with `NDTEST_LOG_DBG=true meson test`, inspect with:
+	#    head -n 7 $(ls -1t build/journal-*.log | tac)
+	#    journalctl --since='- 5 min' -o short-precise -g 'test/common'
+
 	# validate no WARN or lockdep report during the run
-	sleep 1
-	log=$(journalctl -r -k --since "-$((SECONDS+1))s")
+	log=$(journalctl -r -k --since "$NDTEST_START")
 	grep -q "Call Trace" <<< "$log" && err "$1"
 	true
+
+	# Log anchor, especially useful when running tests back to back
+	printf "<5>%s@%ds: test/common: check_dmesg() OK\n" "$test_basename" "$SECONDS" > /dev/kmsg
+
+	if "$NDTEST_LOG_DBG"; then
+	    log_stress from_check_dmesg
+	fi
+}
+
+# While they should, many tests don't use check_dmesg(). So double down here. Also, this
+# runs later which is better.
+# Before enabling NDTEST_LOG_DBG=true, make sure no test started defining its own
+# EXIT trap.
+if "$NDTEST_LOG_DBG"; then
+    trap 'log_stress from_trap' EXIT
+fi
+
+log_stress()
+{
+	printf '<3>%s@%ds: NDTEST_LOG_DBG Call Trace; trying to break the next check_dmesg() %s\n' \
+		"$test_basename" "$SECONDS" "$1" > /dev/kmsg
 }
 
 # CXL COMMON
-- 
2.50.1

Re: [ndctl PATCH 3/3] test/common: stop relying on bash $SECONDS in check_dmesg()

[Dave Jiang]

On 7/24/25 3:00 PM, marc.herbert@linux.intel.com wrote:
> From: Marc Herbert <marc.herbert@linux.intel.com>
> 
> Stop relying on the imprecise bash $SECONDS variable as a test start
> timestamp when scanning the logs for issues.
> 
> $SECONDS was convenient because it came "for free" and did not require
> any time_init(). But it was not fine-grained enough and its rounding
> process is not even documented. Keep using $SECONDS in log messages
> where it is easy to use and more user-friendly than bare timestamps, but
> switch the critical journalctl scan to a new, absolute NDTEST_START
> timestamp initialized when test/common is sourced. Use a SECONDS-based,
> rough sanity check in time_init() to make sure test/common is always
> sourced early.
> 
> Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>

Reviewed-by: Dave Jiang <dave.jiang@intel.com>

Looks ok to me, but I'm not great with bash scripting or journalctl. 

> ---
>  test/common | 52 ++++++++++++++++++++++++++++++++++++++++++++++++++--
>  1 file changed, 50 insertions(+), 2 deletions(-)
> 
> diff --git a/test/common b/test/common
> index 2d076402ef7c..0214c6aaed5f 100644
> --- a/test/common
> +++ b/test/common
> @@ -15,6 +15,25 @@ err()
>  	exit "$rc"
>  }
>  
> +# Initialize the NDTEST_START timestamp used to scan the logs.
> +# Insert an anchor/bookmark in the logs to quickly locate the start of any test.
> +time_init()
> +{
> +	# Refuse to run if anything lasted for too long before this point
> +	# because that would make NDTEST_START incorrect.
> +	test "$SECONDS" -le 1 || err 'test/common must be included first!'
> +
> +	NDTEST_START=$(LC_TIME=C date '+%F %T.%3N')
> +
> +	# Log anchor, especially useful when running tests back to back
> +	printf "<5>%s@%ds: sourcing test/common: NDTEST_START=%s\n" \
> +		"$test_basename" "$SECONDS" "$NDTEST_START" > /dev/kmsg
> +
> +	# Default value, can be overridden by the environment
> +	: "${NDTEST_LOG_DBG:=false}"
> +}
> +time_init
> +
>  # Global variables
>  
>  # NDCTL
> @@ -147,11 +166,40 @@ json2var()
>  # $1: line number where this is called
>  check_dmesg()
>  {
> +	if "$NDTEST_LOG_DBG"; then
> +		# Keep a record of which log lines we scanned
> +		journalctl -q -b --since "$NDTEST_START" \
> +			-o short-precise > journal-"$(basename "$0")".log
> +	fi
> +	# After enabling with `NDTEST_LOG_DBG=true meson test`, inspect with:
> +	#    head -n 7 $(ls -1t build/journal-*.log | tac)
> +	#    journalctl --since='- 5 min' -o short-precise -g 'test/common'
> +
>  	# validate no WARN or lockdep report during the run
> -	sleep 1
> -	log=$(journalctl -r -k --since "-$((SECONDS+1))s")
> +	log=$(journalctl -r -k --since "$NDTEST_START")
>  	grep -q "Call Trace" <<< "$log" && err "$1"
>  	true
> +
> +	# Log anchor, especially useful when running tests back to back
> +	printf "<5>%s@%ds: test/common: check_dmesg() OK\n" "$test_basename" "$SECONDS" > /dev/kmsg
> +
> +	if "$NDTEST_LOG_DBG"; then
> +	    log_stress from_check_dmesg
> +	fi
> +}
> +
> +# While they should, many tests don't use check_dmesg(). So double down here. Also, this
> +# runs later which is better.
> +# Before enabling NDTEST_LOG_DBG=true, make sure no test started defining its own
> +# EXIT trap.
> +if "$NDTEST_LOG_DBG"; then
> +    trap 'log_stress from_trap' EXIT
> +fi
> +
> +log_stress()
> +{
> +	printf '<3>%s@%ds: NDTEST_LOG_DBG Call Trace; trying to break the next check_dmesg() %s\n' \
> +		"$test_basename" "$SECONDS" "$1" > /dev/kmsg
>  }
>  
>  # CXL COMMON

Re: [ndctl PATCH 3/3] test/common: stop relying on bash $SECONDS in check_dmesg()

[Alison Schofield]

> 
> On 7/24/25 3:00 PM, marc.herbert@linux.intel.com wrote:
> > From: Marc Herbert <marc.herbert@linux.intel.com>
> > 
> > Stop relying on the imprecise bash $SECONDS variable as a test start
> > timestamp when scanning the logs for issues.
> > 
> > $SECONDS was convenient because it came "for free" and did not require
> > any time_init(). But it was not fine-grained enough and its rounding
> > process is not even documented. Keep using $SECONDS in log messages
> > where it is easy to use and more user-friendly than bare timestamps, but
> > switch the critical journalctl scan to a new, absolute NDTEST_START
> > timestamp initialized when test/common is sourced. Use a SECONDS-based,
> > rough sanity check in time_init() to make sure test/common is always
> > sourced early.

This patch has one fix, plus 4 while-we-are-at-it's, with only one of the
latter mentioned in the commit message. 

Limit this patch to fixing the known problem - replacing $SECONDS with an
initialized NDTEST_START for accurate log scanning. You could reasonably
include the log anchor additions since those help folks who view the dmesg
log in one go and tie directly to the timing fix. Then, if there is still
justification for the other debug functionality after we've tightened up
the timing, add them in a separate patch with proper explanation of what
problem they solve.

The commit message is explaining the drawbacks of seconds, but not
mentioning why that is a problem for ndctl. This previous text, captured
the issue:

>> Using the bash variable 'SECONDS' plus 1 for searching the
>> dmesg log sometimes led to one test picking up error messages
>> from the previous test when run as a suite. SECONDS alone may
>> miss some logs, but SECONDS + 1 is just as often too great.

Then state what the patch does to resolve it.
Initialize and use a timestamp with ms granularity with journalctl.

a few comments on the implementation...

> > 
> > Signed-off-by: Marc Herbert <marc.herbert@linux.intel.com>
> > ---
> >  test/common | 52 ++++++++++++++++++++++++++++++++++++++++++++++++++--
> >  1 file changed, 50 insertions(+), 2 deletions(-)
> > 
> > diff --git a/test/common b/test/common
> > index 2d076402ef7c..0214c6aaed5f 100644
> > --- a/test/common
> > +++ b/test/common
> > @@ -15,6 +15,25 @@ err()
> >  	exit "$rc"
> >  }
> >  
> > +# Initialize the NDTEST_START timestamp used to scan the logs.
> > +# Insert an anchor/bookmark in the logs to quickly locate the start of any test.
> > +time_init()
> > +{
> > +	# Refuse to run if anything lasted for too long before this point
> > +	# because that would make NDTEST_START incorrect.
> > +	test "$SECONDS" -le 1 || err 'test/common must be included first!'

Agree w previous reviewer comments, this is not needed.

> > +
> > +	NDTEST_START=$(LC_TIME=C date '+%F %T.%3N')
> > +
> > +	# Log anchor, especially useful when running tests back to back
> > +	printf "<5>%s@%ds: sourcing test/common: NDTEST_START=%s\n" \
> > +		"$test_basename" "$SECONDS" "$NDTEST_START" > /dev/kmsg
> > +
> > +	# Default value, can be overridden by the environment
> > +	: "${NDTEST_LOG_DBG:=false}"
> > +}
> > +time_init
> > +
> >  # Global variables
> >  
> >  # NDCTL
> > @@ -147,11 +166,40 @@ json2var()
> >  # $1: line number where this is called
> >  check_dmesg()
> >  {
> > +	if "$NDTEST_LOG_DBG"; then
> > +		# Keep a record of which log lines we scanned
> > +		journalctl -q -b --since "$NDTEST_START" \
> > +			-o short-precise > journal-"$(basename "$0")".log
> > +	fi
> > +	# After enabling with `NDTEST_LOG_DBG=true meson test`, inspect with:
> > +	#    head -n 7 $(ls -1t build/journal-*.log | tac)
> > +	#    journalctl --since='- 5 min' -o short-precise -g 'test/common'
> > +
> >  	# validate no WARN or lockdep report during the run
> > -	sleep 1
> > -	log=$(journalctl -r -k --since "-$((SECONDS+1))s")
> > +	log=$(journalctl -r -k --since "$NDTEST_START")
> >  	grep -q "Call Trace" <<< "$log" && err "$1"
> >  	true
> > +
> > +	# Log anchor, especially useful when running tests back to back
> > +	printf "<5>%s@%ds: test/common: check_dmesg() OK\n" "$test_basename" "$SECONDS" > /dev/kmsg
> > +
> > +	if "$NDTEST_LOG_DBG"; then
> > +	    log_stress from_check_dmesg
> > +	fi
> > +}
> > +
> > +# While they should, many tests don't use check_dmesg().

I suspect we get more value by directly going after the outliers like
scripts not checking dmesg, or unit tests not wrapped in scripts.
(wrapping unit tests in scripts would be a new requirement)

Although not clear what the below code has to do with tests that
don't check_dmesg().

> > So double down here. Also, this
> > +# runs later which is better.
> > +# Before enabling NDTEST_LOG_DBG=true, make sure no test started defining its own
> > +# EXIT trap.
> > +if "$NDTEST_LOG_DBG"; then
> > +    trap 'log_stress from_trap' EXIT
> > +fi
> > +
> > +log_stress()
> > +{
> > +	printf '<3>%s@%ds: NDTEST_LOG_DBG Call Trace; trying to break the next check_dmesg() %s\n' \
> > +		"$test_basename" "$SECONDS" "$1" > /dev/kmsg
> >  }
> >  
> >  # CXL COMMON
> 

Re: test/common: stop relying on bash $SECONDS in check_dmesg()

[Alison Schofield]

Marc - There is something off with the patchset format.
The cover letter is usually Patch 0, so this would look like
like:

[ndctl PATCH 0/3] test/common: stop relying on bash $SECONDS in check_dmesg()
[ndctl PATCH 1/3] test/common: add missing quotes
[ndctl PATCH 2/3] test/common: move err() function at the top
[ndctl PATCH 3/3] test/common: stop relying on bash $SECONDS in check_dmesg()

The cover letter commit message should be general, not same as one of
it's child patches. This ship has sailed, but for next time take a
closer look at what your patch sending tool is generating.


On Thu, Jul 24, 2025 at 10:00:43PM +0000, marc.herbert@linux.intel.com wrote:
> As requested, this is the broken-down, first part of
>   https://lore.kernel.org/linux-cxl/20250611235256.3866724-1-marc.herbert@linux.intel.com/
>   test: fail on unexpected kernel error & warning, not just "Call Trace"
> 
> I will resubmit the rest after the review of this first part is
> completed. The different parts are logically separate (different
> "features") but they are interleaved in the same function and I don't
> really have the time to fix one git conflict per review comment. 
> 
> While it is a requirement to catch warnings and errors later, the
> better accuracy provided by this first part is useful alone. If you
> are interested in what's next, just look at the bigger patch above.
> You don't have to!
>