[PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Kees Cook]

Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
test") solves the problem of kselftest_harness.h-using binary tests
possibly hanging forever. However, scripts and other binaries can still
hang forever. This adds a global timeout to each test script run.

To make this configurable (e.g. as needed in the "rtc" test case),
include a new per-test-directory "settings" file (similar to "config")
that can contain kselftest-specific settings. The first recognized field
is "timeout".

Additionally, this splits the reporting for timeouts into a specific
"TIMEOUT" not-ok (and adds exit code reporting in the remaining case).

Signed-off-by: Kees Cook <keescook@chromium.org>
---
 tools/testing/selftests/kselftest/runner.sh | 36 +++++++++++++++++++--
 tools/testing/selftests/rtc/settings        |  1 +
 2 files changed, 34 insertions(+), 3 deletions(-)
 create mode 100644 tools/testing/selftests/rtc/settings

diff --git a/tools/testing/selftests/kselftest/runner.sh b/tools/testing/selftests/kselftest/runner.sh
index 00c9020bdda8..84de7bc74f2c 100644
--- a/tools/testing/selftests/kselftest/runner.sh
+++ b/tools/testing/selftests/kselftest/runner.sh
@@ -3,9 +3,14 @@
 #
 # Runs a set of tests in a given subdirectory.
 export skip_rc=4
+export timeout_rc=124
 export logfile=/dev/stdout
 export per_test_logging=
 
+# Defaults for "settings" file fields:
+# "timeout" how many seconds to let each test run before failing.
+export kselftest_default_timeout=45
+
 # There isn't a shell-agnostic way to find the path of a sourced file,
 # so we must rely on BASE_DIR being set to find other tools.
 if [ -z "$BASE_DIR" ]; then
@@ -24,6 +29,16 @@ tap_prefix()
 	fi
 }
 
+tap_timeout()
+{
+	# Make sure tests will time out if utility is available.
+	if [ -x /usr/bin/timeout ] ; then
+		/usr/bin/timeout "$kselftest_timeout" "$1"
+	else
+		"$1"
+	fi
+}
+
 run_one()
 {
 	DIR="$1"
@@ -32,6 +47,18 @@ run_one()
 
 	BASENAME_TEST=$(basename $TEST)
 
+	# Reset any "settings"-file variables.
+	export kselftest_timeout="$kselftest_default_timeout"
+	# Load per-test-directory kselftest "settings" file.
+	settings="$BASE_DIR/$DIR/settings"
+	if [ -r "$settings" ] ; then
+		while read line ; do
+			field=$(echo "$line" | cut -d= -f1)
+			value=$(echo "$line" | cut -d= -f2-)
+			eval "kselftest_$field"="$value"
+		done < "$settings"
+	fi
+
 	TEST_HDR_MSG="selftests: $DIR: $BASENAME_TEST"
 	echo "# $TEST_HDR_MSG"
 	if [ ! -x "$TEST" ]; then
@@ -44,14 +71,17 @@ run_one()
 		echo "not ok $test_num $TEST_HDR_MSG"
 	else
 		cd `dirname $TEST` > /dev/null
-		(((((./$BASENAME_TEST 2>&1; echo $? >&3) |
+		((((( tap_timeout ./$BASENAME_TEST 2>&1; echo $? >&3) |
 			tap_prefix >&4) 3>&1) |
 			(read xs; exit $xs)) 4>>"$logfile" &&
 		echo "ok $test_num $TEST_HDR_MSG") ||
-		(if [ $? -eq $skip_rc ]; then	\
+		(rc=$?;	\
+		if [ $rc -eq $skip_rc ]; then	\
 			echo "not ok $test_num $TEST_HDR_MSG # SKIP"
+		elif [ $rc -eq $timeout_rc ]; then \
+			echo "not ok $test_num $TEST_HDR_MSG # TIMEOUT"
 		else
-			echo "not ok $test_num $TEST_HDR_MSG"
+			echo "not ok $test_num $TEST_HDR_MSG # exit=$rc"
 		fi)
 		cd - >/dev/null
 	fi
diff --git a/tools/testing/selftests/rtc/settings b/tools/testing/selftests/rtc/settings
new file mode 100644
index 000000000000..ba4d85f74cd6
--- /dev/null
+++ b/tools/testing/selftests/rtc/settings
@@ -0,0 +1 @@
+timeout=90
-- 
2.17.1


-- 
Kees Cook

Re: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Alexandre Belloni]

On 19/09/2019 11:06:44-0700, Kees Cook wrote:
> Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
> test") solves the problem of kselftest_harness.h-using binary tests
> possibly hanging forever. However, scripts and other binaries can still
> hang forever. This adds a global timeout to each test script run.
> 
> To make this configurable (e.g. as needed in the "rtc" test case),
> include a new per-test-directory "settings" file (similar to "config")
> that can contain kselftest-specific settings. The first recognized field
> is "timeout".
> 

Seems good to me. I was also wondering whether this is actually
reasonable to have tests running for so long. I wanted to discuss that
at LPC but I missed the session.

> Additionally, this splits the reporting for timeouts into a specific
> "TIMEOUT" not-ok (and adds exit code reporting in the remaining case).
> 
> Signed-off-by: Kees Cook <keescook@chromium.org>
> ---
>  tools/testing/selftests/kselftest/runner.sh | 36 +++++++++++++++++++--
>  tools/testing/selftests/rtc/settings        |  1 +
>  2 files changed, 34 insertions(+), 3 deletions(-)
>  create mode 100644 tools/testing/selftests/rtc/settings
> 
> diff --git a/tools/testing/selftests/kselftest/runner.sh b/tools/testing/selftests/kselftest/runner.sh
> index 00c9020bdda8..84de7bc74f2c 100644
> --- a/tools/testing/selftests/kselftest/runner.sh
> +++ b/tools/testing/selftests/kselftest/runner.sh
> @@ -3,9 +3,14 @@
>  #
>  # Runs a set of tests in a given subdirectory.
>  export skip_rc=4
> +export timeout_rc=124
>  export logfile=/dev/stdout
>  export per_test_logging=
>  
> +# Defaults for "settings" file fields:
> +# "timeout" how many seconds to let each test run before failing.
> +export kselftest_default_timeout=45
> +
>  # There isn't a shell-agnostic way to find the path of a sourced file,
>  # so we must rely on BASE_DIR being set to find other tools.
>  if [ -z "$BASE_DIR" ]; then
> @@ -24,6 +29,16 @@ tap_prefix()
>  	fi
>  }
>  
> +tap_timeout()
> +{
> +	# Make sure tests will time out if utility is available.
> +	if [ -x /usr/bin/timeout ] ; then
> +		/usr/bin/timeout "$kselftest_timeout" "$1"
> +	else
> +		"$1"
> +	fi
> +}
> +
>  run_one()
>  {
>  	DIR="$1"
> @@ -32,6 +47,18 @@ run_one()
>  
>  	BASENAME_TEST=$(basename $TEST)
>  
> +	# Reset any "settings"-file variables.
> +	export kselftest_timeout="$kselftest_default_timeout"
> +	# Load per-test-directory kselftest "settings" file.
> +	settings="$BASE_DIR/$DIR/settings"
> +	if [ -r "$settings" ] ; then
> +		while read line ; do
> +			field=$(echo "$line" | cut -d= -f1)
> +			value=$(echo "$line" | cut -d= -f2-)
> +			eval "kselftest_$field"="$value"
> +		done < "$settings"
> +	fi
> +
>  	TEST_HDR_MSG="selftests: $DIR: $BASENAME_TEST"
>  	echo "# $TEST_HDR_MSG"
>  	if [ ! -x "$TEST" ]; then
> @@ -44,14 +71,17 @@ run_one()
>  		echo "not ok $test_num $TEST_HDR_MSG"
>  	else
>  		cd `dirname $TEST` > /dev/null
> -		(((((./$BASENAME_TEST 2>&1; echo $? >&3) |
> +		((((( tap_timeout ./$BASENAME_TEST 2>&1; echo $? >&3) |
>  			tap_prefix >&4) 3>&1) |
>  			(read xs; exit $xs)) 4>>"$logfile" &&
>  		echo "ok $test_num $TEST_HDR_MSG") ||
> -		(if [ $? -eq $skip_rc ]; then	\
> +		(rc=$?;	\
> +		if [ $rc -eq $skip_rc ]; then	\
>  			echo "not ok $test_num $TEST_HDR_MSG # SKIP"
> +		elif [ $rc -eq $timeout_rc ]; then \
> +			echo "not ok $test_num $TEST_HDR_MSG # TIMEOUT"
>  		else
> -			echo "not ok $test_num $TEST_HDR_MSG"
> +			echo "not ok $test_num $TEST_HDR_MSG # exit=$rc"
>  		fi)
>  		cd - >/dev/null
>  	fi
> diff --git a/tools/testing/selftests/rtc/settings b/tools/testing/selftests/rtc/settings
> new file mode 100644
> index 000000000000..ba4d85f74cd6
> --- /dev/null
> +++ b/tools/testing/selftests/rtc/settings
> @@ -0,0 +1 @@
> +timeout=90
> -- 
> 2.17.1
> 
> 
> -- 
> Kees Cook

-- 
Alexandre Belloni, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com

Re: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[shuah]

On 9/19/19 12:55 PM, Alexandre Belloni wrote:
> On 19/09/2019 11:06:44-0700, Kees Cook wrote:
>> Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
>> test") solves the problem of kselftest_harness.h-using binary tests
>> possibly hanging forever. However, scripts and other binaries can still
>> hang forever. This adds a global timeout to each test script run.
>>

Timeout is good, but really tests should not hang. So we have to somehow
indicate that the test needs to be fixed.

This timeout is a band-aid and not real solution for the problem. This
arbitrary value doesn't take into account that the test(s) in that
particular directory (TARGET) could be running normally and working
through all the tests.

We need some way to differentiate the two cases.

>> To make this configurable (e.g. as needed in the "rtc" test case),
>> include a new per-test-directory "settings" file (similar to "config")
>> that can contain kselftest-specific settings. The first recognized field
>> is "timeout".
>>
> 
> Seems good to me. I was also wondering whether this is actually
> reasonable to have tests running for so long. I wanted to discuss that
> at LPC but I missed the session.
> 

There is the individual test times and overall kselftest run time. We
have lots of tests now and it does take long.

>> Additionally, this splits the reporting for timeouts into a specific
>> "TIMEOUT" not-ok (and adds exit code reporting in the remaining case).
>>
>> Signed-off-by: Kees Cook <keescook@chromium.org>
>> ---
>>   tools/testing/selftests/kselftest/runner.sh | 36 +++++++++++++++++++--
>>   tools/testing/selftests/rtc/settings        |  1 +
>>   2 files changed, 34 insertions(+), 3 deletions(-)
>>   create mode 100644 tools/testing/selftests/rtc/settings
>>
>> diff --git a/tools/testing/selftests/kselftest/runner.sh b/tools/testing/selftests/kselftest/runner.sh
>> index 00c9020bdda8..84de7bc74f2c 100644
>> --- a/tools/testing/selftests/kselftest/runner.sh
>> +++ b/tools/testing/selftests/kselftest/runner.sh
>> @@ -3,9 +3,14 @@
>>   #
>>   # Runs a set of tests in a given subdirectory.
>>   export skip_rc=4
>> +export timeout_rc=124
>>   export logfile=/dev/stdout
>>   export per_test_logging=
>>   
>> +# Defaults for "settings" file fields:
>> +# "timeout" how many seconds to let each test run before failing.
>> +export kselftest_default_timeout=45
>> +
>>   # There isn't a shell-agnostic way to find the path of a sourced file,
>>   # so we must rely on BASE_DIR being set to find other tools.
>>   if [ -z "$BASE_DIR" ]; then
>> @@ -24,6 +29,16 @@ tap_prefix()
>>   	fi
>>   }
>>   
>> +tap_timeout()
>> +{
>> +	# Make sure tests will time out if utility is available.
>> +	if [ -x /usr/bin/timeout ] ; then
>> +		/usr/bin/timeout "$kselftest_timeout" "$1"
>> +	else
>> +		"$1"
>> +	fi
>> +}
>> +
>>   run_one()
>>   {
>>   	DIR="$1"
>> @@ -32,6 +47,18 @@ run_one()
>>   
>>   	BASENAME_TEST=$(basename $TEST)
>>   
>> +	# Reset any "settings"-file variables.
>> +	export kselftest_timeout="$kselftest_default_timeout"
>> +	# Load per-test-directory kselftest "settings" file.
>> +	settings="$BASE_DIR/$DIR/settings"
>> +	if [ -r "$settings" ] ; then
>> +		while read line ; do
>> +			field=$(echo "$line" | cut -d= -f1)
>> +			value=$(echo "$line" | cut -d= -f2-)
>> +			eval "kselftest_$field"="$value"
>> +		done < "$settings"
>> +	fi
>> +
>>   	TEST_HDR_MSG="selftests: $DIR: $BASENAME_TEST"
>>   	echo "# $TEST_HDR_MSG"
>>   	if [ ! -x "$TEST" ]; then
>> @@ -44,14 +71,17 @@ run_one()
>>   		echo "not ok $test_num $TEST_HDR_MSG"
>>   	else
>>   		cd `dirname $TEST` > /dev/null
>> -		(((((./$BASENAME_TEST 2>&1; echo $? >&3) |
>> +		((((( tap_timeout ./$BASENAME_TEST 2>&1; echo $? >&3) |
>>   			tap_prefix >&4) 3>&1) |
>>   			(read xs; exit $xs)) 4>>"$logfile" &&
>>   		echo "ok $test_num $TEST_HDR_MSG") ||
>> -		(if [ $? -eq $skip_rc ]; then	\
>> +		(rc=$?;	\
>> +		if [ $rc -eq $skip_rc ]; then	\
>>   			echo "not ok $test_num $TEST_HDR_MSG # SKIP"
>> +		elif [ $rc -eq $timeout_rc ]; then \
>> +			echo "not ok $test_num $TEST_HDR_MSG # TIMEOUT"
>>   		else
>> -			echo "not ok $test_num $TEST_HDR_MSG"
>> +			echo "not ok $test_num $TEST_HDR_MSG # exit=$rc"
>>   		fi)
>>   		cd - >/dev/null
>>   	fi
>> diff --git a/tools/testing/selftests/rtc/settings b/tools/testing/selftests/rtc/settings
>> new file mode 100644
>> index 000000000000..ba4d85f74cd6
>> --- /dev/null
>> +++ b/tools/testing/selftests/rtc/settings
>> @@ -0,0 +1 @@
>> +timeout=90
>> -- 
>> 2.17.1
>>
>>
>> -- 
>> Kees Cook
> 

thanks,
-- Shuah

RE: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Tim.Bird]

> -----Original Message-----
> From: Kees Cook
> 
> Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
> test") solves the problem of kselftest_harness.h-using binary tests
> possibly hanging forever. However, scripts and other binaries can still
> hang forever. This adds a global timeout to each test script run.
> 
> To make this configurable (e.g. as needed in the "rtc" test case),
> include a new per-test-directory "settings" file (similar to "config")
> that can contain kselftest-specific settings. The first recognized field
> is "timeout".

OK - this is quite interesting.  I have had on my to-do list an action
item to propose the creation of a file (or a standard kerneldoc string)
to hold CI-related meta-data (of which timeout is one example).

What other meta-data did you have in mind?

I would like (that Fuego, and probably other CI systems would like) to have
 access to data like test dependencies, descriptions, and results interpretation
that would be beneficial for both CI systems (using them to control test invocations and scheduling), as
well as users who are trying to interpret and handle the test results.
So this concept is a very welcome addition to kselftest.

LTP is in the process of adopting a new system for expressing and handling their test meta-data.
See the discussion at: 
https://lists.yoctoproject.org/pipermail/automated-testing/2019-August/000471.html
and the prototype implementation at:
https://github.com/metan-ucw/ltp/tree/master/docparse

I realize that that system is coupled pretty tightly to LTP, but conceptually
some of the same type of information would be valuable for kselftest tests.
One example of a specific field that would be handy is 'need_root'.

It would be nice to avoid proliferation of such meta-data schemas (that is
field names), so maybe we can have a discussion about this before adopting
something?

Just FYI, I'm OK with the name 'timeout'.  I think that's pretty much universally
used by all CI runners I'm aware of to indicate the test timeout value.  But
before adopting other fields it would be good to start comparing notes
and not invent a bunch of new field names for concepts that are already in
other systems.

> 
> Additionally, this splits the reporting for timeouts into a specific
> "TIMEOUT" not-ok (and adds exit code reporting in the remaining case).
> 
> Signed-off-by: Kees Cook <keescook@chromium.org>
> ---
>  tools/testing/selftests/kselftest/runner.sh | 36 +++++++++++++++++++--
>  tools/testing/selftests/rtc/settings        |  1 +
>  2 files changed, 34 insertions(+), 3 deletions(-)
>  create mode 100644 tools/testing/selftests/rtc/settings
> 
> diff --git a/tools/testing/selftests/kselftest/runner.sh
> b/tools/testing/selftests/kselftest/runner.sh
> index 00c9020bdda8..84de7bc74f2c 100644
> --- a/tools/testing/selftests/kselftest/runner.sh
> +++ b/tools/testing/selftests/kselftest/runner.sh
> @@ -3,9 +3,14 @@
>  #
>  # Runs a set of tests in a given subdirectory.
>  export skip_rc=4
> +export timeout_rc=124
what are the units here?  I presume seconds?

>  export logfile=/dev/stdout
>  export per_test_logging=
> 
> +# Defaults for "settings" file fields:
> +# "timeout" how many seconds to let each test run before failing.
> +export kselftest_default_timeout=45
> +
>  # There isn't a shell-agnostic way to find the path of a sourced file,
>  # so we must rely on BASE_DIR being set to find other tools.
>  if [ -z "$BASE_DIR" ]; then
> @@ -24,6 +29,16 @@ tap_prefix()
>  	fi
>  }
> 
> +tap_timeout()
> +{
> +	# Make sure tests will time out if utility is available.
> +	if [ -x /usr/bin/timeout ] ; then
> +		/usr/bin/timeout "$kselftest_timeout" "$1"
> +	else
> +		"$1"
> +	fi
> +}
> +
>  run_one()
>  {
>  	DIR="$1"
> @@ -32,6 +47,18 @@ run_one()
> 
>  	BASENAME_TEST=$(basename $TEST)
> 
> +	# Reset any "settings"-file variables.
> +	export kselftest_timeout="$kselftest_default_timeout"
> +	# Load per-test-directory kselftest "settings" file.
> +	settings="$BASE_DIR/$DIR/settings"
> +	if [ -r "$settings" ] ; then
> +		while read line ; do
> +			field=$(echo "$line" | cut -d= -f1)
> +			value=$(echo "$line" | cut -d= -f2-)
> +			eval "kselftest_$field"="$value"
> +		done < "$settings"
> +	fi
> +
>  	TEST_HDR_MSG="selftests: $DIR: $BASENAME_TEST"
>  	echo "# $TEST_HDR_MSG"
>  	if [ ! -x "$TEST" ]; then
> @@ -44,14 +71,17 @@ run_one()
>  		echo "not ok $test_num $TEST_HDR_MSG"
>  	else
>  		cd `dirname $TEST` > /dev/null
> -		(((((./$BASENAME_TEST 2>&1; echo $? >&3) |
> +		((((( tap_timeout ./$BASENAME_TEST 2>&1; echo $? >&3) |
>  			tap_prefix >&4) 3>&1) |
>  			(read xs; exit $xs)) 4>>"$logfile" &&
>  		echo "ok $test_num $TEST_HDR_MSG") ||
> -		(if [ $? -eq $skip_rc ]; then	\
> +		(rc=$?;	\
> +		if [ $rc -eq $skip_rc ]; then	\
>  			echo "not ok $test_num $TEST_HDR_MSG # SKIP"
> +		elif [ $rc -eq $timeout_rc ]; then \
> +			echo "not ok $test_num $TEST_HDR_MSG #
> TIMEOUT"
This is an extension to the TAP protocol (well, not strictly, since it is in a comment),
but it should be documented.

I took an action item at the CKI hackfest to rigorously document the
details of how kselftest has extended (or augmented) TAP.  For example
our indentation mechanism for sub-tests.  You and I talked about this
a bit at Plumbers, but I'd like to follow up and add something
to Documentation/dev-tools/kselftest.rst so users and CI systems
can know how to appropriately parse and manage kselftest TAP output.

I'll start a separate thread on that when I get to documenting it,
but this would definitely be an addition to that documentation.

>  		else
> -			echo "not ok $test_num $TEST_HDR_MSG"
> +			echo "not ok $test_num $TEST_HDR_MSG #
> exit=$rc"
Is this also something new to kselftest's TAP output that should be documented?

>  		fi)
>  		cd - >/dev/null
>  	fi
> diff --git a/tools/testing/selftests/rtc/settings
> b/tools/testing/selftests/rtc/settings
> new file mode 100644
> index 000000000000..ba4d85f74cd6
> --- /dev/null
> +++ b/tools/testing/selftests/rtc/settings
> @@ -0,0 +1 @@
> +timeout=90

This is introducing a schema for meta-data naming, and a first field name.
I have no problem with this one, but it might be worth comparing it with
names expected by various kselftest-calling  CI systems.  I'll try to work
on this shortly and report back any issues.

Thanks for this.  I think this points us in an interesting new direction.
 -- Tim

RE: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Tim.Bird]

> -----Original Message-----
> From: shuah
> 
> On 9/19/19 12:55 PM, Alexandre Belloni wrote:
> > On 19/09/2019 11:06:44-0700, Kees Cook wrote:
> >> Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
> >> test") solves the problem of kselftest_harness.h-using binary tests
> >> possibly hanging forever. However, scripts and other binaries can still
> >> hang forever. This adds a global timeout to each test script run.
> >>
> 
> Timeout is good, but really tests should not hang. So we have to somehow
> indicate that the test needs to be fixed.

Well, a test hanging is something that might indicate either a failing 
in the test, or the detection of an actual problem.

> 
> This timeout is a band-aid and not real solution for the problem. This
> arbitrary value doesn't take into account that the test(s) in that
> particular directory (TARGET) could be running normally and working
> through all the tests.
Yes.  Also, having a single timeout value doesn't reflect the need
to test on different hardware with potentially huge differences in
CPU speed (or other resource performance differences).

Since kselftest has a policy of having each test run quickly, this is somewhat
mitigated.  But still, some embedded boards are running magnitudes
slower than your "average" enterprise Linux machine.  Finding a timeout
that can handle all hardware cases is difficult.
 -- Tim

> 
> We need some way to differentiate the two cases.
Agreed.
> 
> >> To make this configurable (e.g. as needed in the "rtc" test case),
> >> include a new per-test-directory "settings" file (similar to "config")
> >> that can contain kselftest-specific settings. The first recognized field
> >> is "timeout".
> >>
> >
> > Seems good to me. I was also wondering whether this is actually
> > reasonable to have tests running for so long. I wanted to discuss that
> > at LPC but I missed the session.
> >
> 
> There is the individual test times and overall kselftest run time. We
> have lots of tests now and it does take long.
> 
> >> Additionally, this splits the reporting for timeouts into a specific
> >> "TIMEOUT" not-ok (and adds exit code reporting in the remaining case).
> >>
> >> Signed-off-by: Kees Cook <keescook@chromium.org>
> >> ---
> >>   tools/testing/selftests/kselftest/runner.sh | 36
> +++++++++++++++++++--
> >>   tools/testing/selftests/rtc/settings        |  1 +
> >>   2 files changed, 34 insertions(+), 3 deletions(-)
> >>   create mode 100644 tools/testing/selftests/rtc/settings
> >>
> >> diff --git a/tools/testing/selftests/kselftest/runner.sh
> b/tools/testing/selftests/kselftest/runner.sh
> >> index 00c9020bdda8..84de7bc74f2c 100644
> >> --- a/tools/testing/selftests/kselftest/runner.sh
> >> +++ b/tools/testing/selftests/kselftest/runner.sh
> >> @@ -3,9 +3,14 @@
> >>   #
> >>   # Runs a set of tests in a given subdirectory.
> >>   export skip_rc=4
> >> +export timeout_rc=124
> >>   export logfile=/dev/stdout
> >>   export per_test_logging=
> >>
> >> +# Defaults for "settings" file fields:
> >> +# "timeout" how many seconds to let each test run before failing.
> >> +export kselftest_default_timeout=45
> >> +
> >>   # There isn't a shell-agnostic way to find the path of a sourced file,
> >>   # so we must rely on BASE_DIR being set to find other tools.
> >>   if [ -z "$BASE_DIR" ]; then
> >> @@ -24,6 +29,16 @@ tap_prefix()
> >>   	fi
> >>   }
> >>
> >> +tap_timeout()
> >> +{
> >> +	# Make sure tests will time out if utility is available.
> >> +	if [ -x /usr/bin/timeout ] ; then
> >> +		/usr/bin/timeout "$kselftest_timeout" "$1"
> >> +	else
> >> +		"$1"
> >> +	fi
> >> +}
> >> +
> >>   run_one()
> >>   {
> >>   	DIR="$1"
> >> @@ -32,6 +47,18 @@ run_one()
> >>
> >>   	BASENAME_TEST=$(basename $TEST)
> >>
> >> +	# Reset any "settings"-file variables.
> >> +	export kselftest_timeout="$kselftest_default_timeout"
> >> +	# Load per-test-directory kselftest "settings" file.
> >> +	settings="$BASE_DIR/$DIR/settings"
> >> +	if [ -r "$settings" ] ; then
> >> +		while read line ; do
> >> +			field=$(echo "$line" | cut -d= -f1)
> >> +			value=$(echo "$line" | cut -d= -f2-)
> >> +			eval "kselftest_$field"="$value"
> >> +		done < "$settings"
> >> +	fi
> >> +
> >>   	TEST_HDR_MSG="selftests: $DIR: $BASENAME_TEST"
> >>   	echo "# $TEST_HDR_MSG"
> >>   	if [ ! -x "$TEST" ]; then
> >> @@ -44,14 +71,17 @@ run_one()
> >>   		echo "not ok $test_num $TEST_HDR_MSG"
> >>   	else
> >>   		cd `dirname $TEST` > /dev/null
> >> -		(((((./$BASENAME_TEST 2>&1; echo $? >&3) |
> >> +		((((( tap_timeout ./$BASENAME_TEST 2>&1; echo $? >&3) |
> >>   			tap_prefix >&4) 3>&1) |
> >>   			(read xs; exit $xs)) 4>>"$logfile" &&
> >>   		echo "ok $test_num $TEST_HDR_MSG") ||
> >> -		(if [ $? -eq $skip_rc ]; then	\
> >> +		(rc=$?;	\
> >> +		if [ $rc -eq $skip_rc ]; then	\
> >>   			echo "not ok $test_num $TEST_HDR_MSG # SKIP"
> >> +		elif [ $rc -eq $timeout_rc ]; then \
> >> +			echo "not ok $test_num $TEST_HDR_MSG #
> TIMEOUT"
> >>   		else
> >> -			echo "not ok $test_num $TEST_HDR_MSG"
> >> +			echo "not ok $test_num $TEST_HDR_MSG #
> exit=$rc"
> >>   		fi)
> >>   		cd - >/dev/null
> >>   	fi
> >> diff --git a/tools/testing/selftests/rtc/settings
> b/tools/testing/selftests/rtc/settings
> >> new file mode 100644
> >> index 000000000000..ba4d85f74cd6
> >> --- /dev/null
> >> +++ b/tools/testing/selftests/rtc/settings
> >> @@ -0,0 +1 @@
> >> +timeout=90
> >> --
> >> 2.17.1
> >>
> >>
> >> --
> >> Kees Cook
> >
> 
> thanks,
> -- Shuah

RE: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Tim.Bird]

> -----Original Message-----
> From Tim.Bird@sony.com
> 
> > -----Original Message-----
> > From: Kees Cook
> >
> > Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
> > test") solves the problem of kselftest_harness.h-using binary tests
> > possibly hanging forever. However, scripts and other binaries can still
> > hang forever. This adds a global timeout to each test script run.
> >
> > To make this configurable (e.g. as needed in the "rtc" test case),
> > include a new per-test-directory "settings" file (similar to "config")
> > that can contain kselftest-specific settings. The first recognized field
> > is "timeout".
> 
> OK - this is quite interesting.  I have had on my to-do list an action
> item to propose the creation of a file (or a standard kerneldoc string)
> to hold CI-related meta-data (of which timeout is one example).
> 
> What other meta-data did you have in mind?
> 
> I would like (that Fuego, and probably other CI systems would like) to have
>  access to data like test dependencies, descriptions, and results
> interpretation
> that would be beneficial for both CI systems (using them to control test
> invocations and scheduling), as
> well as users who are trying to interpret and handle the test results.
> So this concept is a very welcome addition to kselftest.
> 
> LTP is in the process of adopting a new system for expressing and handling
> their test meta-data.
> See the discussion at:
> https://lists.yoctoproject.org/pipermail/automated-testing/2019-
> August/000471.html
> and the prototype implementation at:
> https://github.com/metan-ucw/ltp/tree/master/docparse
> 
> I realize that that system is coupled pretty tightly to LTP, but conceptually
> some of the same type of information would be valuable for kselftest tests.
> One example of a specific field that would be handy is 'need_root'.
> 
> It would be nice to avoid proliferation of such meta-data schemas (that is
> field names), so maybe we can have a discussion about this before adopting
> something?
> 
> Just FYI, I'm OK with the name 'timeout'.  I think that's pretty much
> universally
> used by all CI runners I'm aware of to indicate the test timeout value.  But
> before adopting other fields it would be good to start comparing notes
> and not invent a bunch of new field names for concepts that are already in
> other systems.
> 
> >
> > Additionally, this splits the reporting for timeouts into a specific
> > "TIMEOUT" not-ok (and adds exit code reporting in the remaining case).
> >
> > Signed-off-by: Kees Cook <keescook@chromium.org>
> > ---
> >  tools/testing/selftests/kselftest/runner.sh | 36 +++++++++++++++++++--
> >  tools/testing/selftests/rtc/settings        |  1 +
> >  2 files changed, 34 insertions(+), 3 deletions(-)
> >  create mode 100644 tools/testing/selftests/rtc/settings
> >
> > diff --git a/tools/testing/selftests/kselftest/runner.sh
> > b/tools/testing/selftests/kselftest/runner.sh
> > index 00c9020bdda8..84de7bc74f2c 100644
> > --- a/tools/testing/selftests/kselftest/runner.sh
> > +++ b/tools/testing/selftests/kselftest/runner.sh
> > @@ -3,9 +3,14 @@
> >  #
> >  # Runs a set of tests in a given subdirectory.
> >  export skip_rc=4
> > +export timeout_rc=124
> what are the units here?  I presume seconds?

Nevermind.  I misread this.  This is the return code from the 'timeout' program, right?
 -- Tim

Re: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Kees Cook]

On Thu, Sep 19, 2019 at 08:49:14PM +0000, Tim.Bird@sony.com wrote:
> > > +export timeout_rc=124
> > what are the units here?  I presume seconds?
> 
> Nevermind.  I misread this.  This is the return code from the 'timeout' program, right?

Correct -- given the skip_rc usage, it felt weird to hard-code it in the
if/else statements.

As for the "45" I chose, that was just to be "more than 30" which was
the per-sub-test for tests built using kselftest_harness.h.

-- 
Kees Cook

Re: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Kees Cook]

On Thu, Sep 19, 2019 at 08:41:42PM +0000, Tim.Bird@sony.com wrote:
> > -----Original Message-----
> > From: Kees Cook
> > 
> > Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
> > test") solves the problem of kselftest_harness.h-using binary tests
> > possibly hanging forever. However, scripts and other binaries can still
> > hang forever. This adds a global timeout to each test script run.
> > 
> > To make this configurable (e.g. as needed in the "rtc" test case),
> > include a new per-test-directory "settings" file (similar to "config")
> > that can contain kselftest-specific settings. The first recognized field
> > is "timeout".
> 
> OK - this is quite interesting.  I have had on my to-do list an action
> item to propose the creation of a file (or a standard kerneldoc string)
> to hold CI-related meta-data (of which timeout is one example).

FWIW, I opt for a "per directory settings" file here because per-test
seemed like overkill.

> What other meta-data did you have in mind?

I figured in the future it could hold details about expected environmental
states (user, namespace, rlimits, etc). For example, I'd like to
indicate that the seccomp tests should be run twice both as root and as
a regular user.

> I would like (that Fuego, and probably other CI systems would like) to have
>  access to data like test dependencies, descriptions, and results interpretation
> that would be beneficial for both CI systems (using them to control test invocations and scheduling), as
> well as users who are trying to interpret and handle the test results.
> So this concept is a very welcome addition to kselftest.

I think this stuff may still be very per-test specific, but regardless,
having it in a single place makes it easy to scrape. :)

> LTP is in the process of adopting a new system for expressing and handling their test meta-data.
> See the discussion at: 
> https://lists.yoctoproject.org/pipermail/automated-testing/2019-August/000471.html
> and the prototype implementation at:
> https://github.com/metan-ucw/ltp/tree/master/docparse

This looks like similar framework details: _how_ to run a test in a
given environment.

> One example of a specific field that would be handy is 'need_root'.

I think describing (possibly multiple) expected environments would be
more useful, but perhaps just user alone would be a nice start.

> It would be nice to avoid proliferation of such meta-data schemas (that is
> field names), so maybe we can have a discussion about this before adopting
> something?
> 
> Just FYI, I'm OK with the name 'timeout'.  I think that's pretty much universally
> used by all CI runners I'm aware of to indicate the test timeout value.  But
> before adopting other fields it would be good to start comparing notes
> and not invent a bunch of new field names for concepts that are already in
> other systems.

Yeah, I figure "timeout" could stand and other things would need more
infrastructure.

> > +		if [ $rc -eq $skip_rc ]; then	\
> >  			echo "not ok $test_num $TEST_HDR_MSG # SKIP"
> > +		elif [ $rc -eq $timeout_rc ]; then \
> > +			echo "not ok $test_num $TEST_HDR_MSG # TIMEOUT"
> This is an extension to the TAP protocol (well, not strictly, since it is in a comment),
> but it should be documented.

Right -- this is a "weird" corner of TAP-14. It says there can be "#"
with everything after it semantically ignored, but that "# SKIP" is
special. I think clarification of the spec here would be to have the
format be:

not ok name name name # DETAIL ignored ignored ignored

Where the meaningful DETAIL words could be SKIP, TIMEOUT, FAIL.

> I took an action item at the CKI hackfest to rigorously document the
> details of how kselftest has extended (or augmented) TAP.  For example
> our indentation mechanism for sub-tests.  You and I talked about this
> a bit at Plumbers, but I'd like to follow up and add something
> to Documentation/dev-tools/kselftest.rst so users and CI systems
> can know how to appropriately parse and manage kselftest TAP output.
> 
> I'll start a separate thread on that when I get to documenting it,
> but this would definitely be an addition to that documentation.
> 
> >  		else
> > -			echo "not ok $test_num $TEST_HDR_MSG"
> > +			echo "not ok $test_num $TEST_HDR_MSG #
> > exit=$rc"
> Is this also something new to kselftest's TAP output that should be documented?

Right, if we made more the "SKIP" meaningful and required a specific
detail here, this could just be "... # FAIL exit=$rc" unless we _wanted_
to make the exit code be parsed. Then maybe "... # EXIT=$rc" ?

> 
> >  		fi)
> >  		cd - >/dev/null
> >  	fi
> > diff --git a/tools/testing/selftests/rtc/settings
> > b/tools/testing/selftests/rtc/settings
> > new file mode 100644
> > index 000000000000..ba4d85f74cd6
> > --- /dev/null
> > +++ b/tools/testing/selftests/rtc/settings
> > @@ -0,0 +1 @@
> > +timeout=90
> 
> This is introducing a schema for meta-data naming, and a first field name.
> I have no problem with this one, but it might be worth comparing it with
> names expected by various kselftest-calling  CI systems.  I'll try to work
> on this shortly and report back any issues.
> 
> Thanks for this.  I think this points us in an interesting new direction.

Cool; I'm glad you like it! I really do want to get timeouts nailed down
since Shuah mentioned that was a pain point. While I solved it for
seccomp via the kselftest_harness.h timeout, there have been other
cases of stalls that aren't handled by that change.

-- 
Kees Cook

Re: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[Kees Cook]

On Thu, Sep 19, 2019 at 02:09:37PM -0600, shuah wrote:
> On 9/19/19 12:55 PM, Alexandre Belloni wrote:
> > On 19/09/2019 11:06:44-0700, Kees Cook wrote:
> > > Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
> > > test") solves the problem of kselftest_harness.h-using binary tests
> > > possibly hanging forever. However, scripts and other binaries can still
> > > hang forever. This adds a global timeout to each test script run.
> > > 
> 
> Timeout is good, but really tests should not hang. So we have to somehow
> indicate that the test needs to be fixed.

Totally agreed, which is why I changed the reporting to call out a
"TIMEOUT" instead of just having it enter the general failure noise.

> This timeout is a band-aid and not real solution for the problem. This
> arbitrary value doesn't take into account that the test(s) in that
> particular directory (TARGET) could be running normally and working
> through all the tests.

Even something that looks like it's making progress may still be hung or
won't finish in a reasonable amount of time.

> We need some way to differentiate the two cases.

I don't think it's unreasonable to declare that no test should take
longer than some default amount of time that can be tweaked via a
"settings" file. It gives the framework the option of easily removing
tests that take "too long", etc. If the "timeout=..." value was made
mandatory for each test directory, then the framework could actually
filter based on expected worst-case run time.

> > > To make this configurable (e.g. as needed in the "rtc" test case),
> > > include a new per-test-directory "settings" file (similar to "config")
> > > that can contain kselftest-specific settings. The first recognized field
> > > is "timeout".
> > > 
> > 
> > Seems good to me. I was also wondering whether this is actually
> > reasonable to have tests running for so long. I wanted to discuss that
> > at LPC but I missed the session.
> > 
> 
> There is the individual test times and overall kselftest run time. We
> have lots of tests now and it does take long.

This patch seeks to implement a "timeout for a single test from
kselftest's perspective". Some "individual" tests have many subtests
(e.g. anything built with kselftest_harness.h) giving us the whole
subtest issue. I think my solution here is a good middle ground: we
specify the max run time for each executed test binary/script.

It's not clear to me if a v2 is needed? Is this patch fine as-is?

Thanks!

-- 
Kees Cook

Re: [PATCH] selftests/kselftest/runner.sh: Add 45 second timeout per test

[shuah]

On 9/19/19 3:17 PM, Kees Cook wrote:
> On Thu, Sep 19, 2019 at 02:09:37PM -0600, shuah wrote:
>> On 9/19/19 12:55 PM, Alexandre Belloni wrote:
>>> On 19/09/2019 11:06:44-0700, Kees Cook wrote:
>>>> Commit a745f7af3cbd ("selftests/harness: Add 30 second timeout per
>>>> test") solves the problem of kselftest_harness.h-using binary tests
>>>> possibly hanging forever. However, scripts and other binaries can still
>>>> hang forever. This adds a global timeout to each test script run.
>>>>
>>
>> Timeout is good, but really tests should not hang. So we have to somehow
>> indicate that the test needs to be fixed.
> 
> Totally agreed, which is why I changed the reporting to call out a
> "TIMEOUT" instead of just having it enter the general failure noise.
> 
>> This timeout is a band-aid and not real solution for the problem. This
>> arbitrary value doesn't take into account that the test(s) in that
>> particular directory (TARGET) could be running normally and working
>> through all the tests.
> 
> Even something that looks like it's making progress may still be hung or
> won't finish in a reasonable amount of time.
> 
>> We need some way to differentiate the two cases.
> 
> I don't think it's unreasonable to declare that no test should take
> longer than some default amount of time that can be tweaked via a
> "settings" file. It gives the framework the option of easily removing
> tests that take "too long", etc. If the "timeout=..." value was made
> mandatory for each test directory, then the framework could actually
> filter based on expected worst-case run time.
> 
>>>> To make this configurable (e.g. as needed in the "rtc" test case),
>>>> include a new per-test-directory "settings" file (similar to "config")
>>>> that can contain kselftest-specific settings. The first recognized field
>>>> is "timeout".
>>>>
>>>
>>> Seems good to me. I was also wondering whether this is actually
>>> reasonable to have tests running for so long. I wanted to discuss that
>>> at LPC but I missed the session.
>>>
>>
>> There is the individual test times and overall kselftest run time. We
>> have lots of tests now and it does take long.
> 
> This patch seeks to implement a "timeout for a single test from
> kselftest's perspective". Some "individual" tests have many subtests
> (e.g. anything built with kselftest_harness.h) giving us the whole
> subtest issue. I think my solution here is a good middle ground: we
> specify the max run time for each executed test binary/script.
> 
> It's not clear to me if a v2 is needed? Is this patch fine as-is?
> 
> Thanks!
> 

v1 is good. I will pull this in for testing. I do like the way it is
done.

thanks,
-- Shuah