[LTP] [PATCH v2 0/3] shell: Fix orphan timeout sleep processes

[LTP] [PATCH v2 0/3] shell: Fix orphan timeout sleep processes

[Joerg Vehlow]

Hi,

Updates to v1: Instead of a c based solution this uses the shell
based fix suggested by Li

J?rg

[LTP] [PATCH v2 1/2] shell: Extend timeout tests

[Joerg Vehlow]

From: Joerg Vehlow <joerg.vehlow@aox-tech.de>

- Add test, that verifies, that the timeout is working as expected.
- Add test case to check if there are processes left,
  after a test finished without running into a timeout.
- Add execution of timeout03.sh and verification of return code.

Signed-off-by: Joerg Vehlow <joerg.vehlow@aox-tech.de>
---
 lib/newlib_tests/shell/test_timeout.sh | 178 ++++++++++++++++++++++---
 lib/newlib_tests/shell/timeout04.sh    |  22 +++
 2 files changed, 179 insertions(+), 21 deletions(-)
 create mode 100755 lib/newlib_tests/shell/timeout04.sh

diff --git a/lib/newlib_tests/shell/test_timeout.sh b/lib/newlib_tests/shell/test_timeout.sh
index 26477d6f2..06f3acf88 100755
--- a/lib/newlib_tests/shell/test_timeout.sh
+++ b/lib/newlib_tests/shell/test_timeout.sh
@@ -1,42 +1,178 @@
 #!/bin/sh
 # SPDX-License-Identifier: GPL-2.0-or-later
 # Copyright (c) 2019 Petr Vorel <pvorel@suse.cz>
+# Copyright (c) 2021 Joerg Vehlow <joerg.vehlow@aox-tech.de>
 
 PATH="$(dirname $0):$(dirname $0)/../../../testcases/lib/:$PATH"
 
+# Test cases are separated by newlines.
+# Every test has the following fields in this order:
+# file
+# timeout_mul
+# use_cat
+# max_runtime
+# expected_exit_code
+# expected passes
+# expected failed
+# expected broken
+# description
+# Whole lines can be commented out using "#"
 DATA="
-timeout01.sh||0
-timeout02.sh||0
-timeout02.sh|foo|2
-timeout02.sh|2|0
-timeout01.sh|2|0
-timeout02.sh|1.1|0
-timeout02.sh|-10|2
-timeout02.sh|-0.1|0
-timeout02.sh|-1.1|2
-timeout02.sh|-10.1|2
+timeout01.sh|     |0|  |0
+timeout02.sh|     |0|  |0
+timeout02.sh|  foo|0|  |2
+timeout02.sh|    2|0|  |0
+timeout01.sh|    2|0|  |0
+timeout02.sh|  1.1|0|  |0
+timeout02.sh|  -10|0|  |2
+timeout02.sh| -0.1|0|  |0
+timeout02.sh| -1.1|0|  |2
+timeout02.sh|-10.1|0|  |2
+timeout03.sh|     |0|12|137| | | |Test kill if test does not terminate by SIGINT
+timeout04.sh|     |0|  |  2|0|0|1|Verify that timeout is enforced
+timeout02.sh|    2|1| 2|   |1|0|0|Test termination of timeout process
 "
 
+# Executes a test
+# Parameter:
+#  - test:    The test to execute
+#  - timeout: The timeout multiplicator (optional)
+#  - use_cat: Pipe the output of the command through cat (optional)
+#             If this is used, the exit code is NOT returned!
+#
+# The function returns the following global variables:
+# - test_exit:     The exit code of the test
+# - test_duration: The duration of the test in seconds
+# - test_output:   The full output of the test
+# - test_passed:   The number of passed tests parsed from the summary
+# - test_failed:   The number of failed tests parsed from the summary
+# - test_broken:   The number of broken tests parsed from the summary
+run_test()
+{
+	local test=$1
+	local timeout=$2
+	local use_cat=$3
+	local tmpfile start end;
+
+	tmpfile=$(mktemp -t ltp_timeout_XXXXXXXX)
+	start=$(date +%s)
+	# We have to use set monitor mode (set -m) here.
+	# In most shells in most cases this creates a
+	# new process group for the next command.
+	# A process group is required for the timeout functionality,
+	# because it sends signals to the whole process group.
+	set -m
+	# The use_cat is for testing if any programm using stdout
+	# is still running, after the test finished.
+	# cat will wait for its stdin to be closed.
+	#
+	# In the pure shell implementation of the timeout handling,
+	# the sleep process was never killed, when a test finished
+	# before the timeout.
+	if [ "$use_cat" = "1" ]; then
+		LTP_TIMEOUT_MUL=$timeout $test 2>&1 | cat >$tmpfile
+	else
+		LTP_TIMEOUT_MUL=$timeout $test 1>$tmpfile 2>&1
+	fi
+	test_exit=$?
+	set +m
+	end=$(date +%s)
+
+	test_duration=$((end - start))
+	test_output=$(cat $tmpfile)
+	rm $tmpfile
+
+	eval $(echo "$test_output" | awk '
+		BEGIN {sum=0} 
+		$1 == "Summary:" {
+			sum=1;
+		}
+		sum && ( \
+			   $1 == "passed" \
+			|| $1 == "failed" \
+			|| $1 == "broken") {
+			print "test_" $1 "=" $2
+		}
+	')
+}
+
 echo "Testing timeout in shell API"
 echo
 
 failed=0
-for i in $DATA; do
-	file=$(echo $i | cut -d'|' -f1)
-	timeout=$(echo $i | cut -d'|' -f2)
-	exp_exit=$(echo $i | cut -d'|' -f3)
-
-	echo "=== $file (LTP_TIMEOUT_MUL='$timeout') ==="
-	LTP_TIMEOUT_MUL=$timeout $file
-	ret=$?
-	if [ $ret -ne $exp_exit ]; then
-		echo "FAILED (exit code: $ret, expected $exp_exit)"
-		failed=$((failed+1))
+test_nr=0
+
+old_ifs="$IFS"
+IFS=$(printf "\n\b")
+
+# Remove comments and empty lines
+CLEANED_DATA=$(echo "$DATA" | sed '/^\s*#/d;/^\s*$/d')
+test_max=$(echo "$CLEANED_DATA" | wc -l)
+for d in $CLEANED_DATA; do
+	IFS="$old_ifs"
+
+	file=$(echo $d | cut -d'|' -f1 | xargs)
+	timeout=$(echo $d | cut -d'|' -f2 | xargs)
+	use_cat=$(echo $d | cut -d'|' -f3 | xargs)
+	max_runtime=$(echo $d | cut -d'|' -f4 | xargs)
+	max_runtime=${max_runtime:--1}
+	exp_exit=$(echo $d | cut -d'|' -f5 | xargs)
+	exp_exit=${exp_exit:--1}
+	exp_passed=$(echo $d | cut -d'|' -f6 | xargs)
+	exp_passed=${exp_passed:--1}
+	exp_failed=$(echo $d | cut -d'|' -f7 | xargs)
+	exp_failed=${exp_failed:--1}
+	exp_broken=$(echo $d | cut -d'|' -f8 | xargs)
+	exp_broken=${exp_broken:--1}
+	description=$(echo $d | cut -d'|' -f9)
+
+	test_nr=$(($test_nr + 1))
+
+	cur_fails=0
+
+	if [ -z "$description" ]; then
+		description="$file (LTP_TIMEOUT_MUL='$timeout')"
+	fi
+
+	echo "=== $test_nr/$test_max $description ==="
+	run_test "$file" "$timeout" "$use_cat"
+
+	if [ $max_runtime -ne -1 ] && [ $test_duration -gt $max_runtime ]; then
+		echo "FAILED (runtime: $test_duration, expected less than $max_runtime)"
+		cur_fails=$((cur_fails + 1))
+	fi
+
+	if [ $exp_passed -ne -1 ] && [ $exp_passed -ne $test_passed ]; then
+		echo "FAILED (passes: $test_passed, expected $exp_passed)"
+		cur_fails=$((cur_fails + 1))
+	fi
+
+	if [ $exp_failed -ne -1 ] && [ $exp_failed -ne $test_failed ]; then
+		echo "FAILED (failed: $test_failed, expected $exp_failed)"
+		cur_fails=$((cur_fails + 1))
+	fi
+
+	if [ $exp_broken -ne -1 ] && [ $exp_broken -ne $test_broken ]; then
+		echo "FAILED (broken: $test_broken, expected $exp_broken)"
+		cur_fails=$((cur_fails + 1))
+	fi
+
+	if [ $exp_exit -ne -1 ] && [ $test_exit -ne $exp_exit ]; then
+		echo "FAILED (exit code: $test_exit, expected $exp_exit)"
+		cur_fails=$((cur_fails + 1))
+	fi
+
+	if [ $cur_fails -gt 0 ]; then
+		failed=$((failed + 1))
+		echo "--------"
+		echo "$test_output"
+		echo "--------"
 	else
 		echo "PASSED"
 	fi
 	echo
 done
+IFS="$old_ifs"
 
 echo "Failed tests: $failed"
 exit $failed
diff --git a/lib/newlib_tests/shell/timeout04.sh b/lib/newlib_tests/shell/timeout04.sh
new file mode 100755
index 000000000..0a6ba053c
--- /dev/null
+++ b/lib/newlib_tests/shell/timeout04.sh
@@ -0,0 +1,22 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0-or-later
+# Copyright (c) 2021 Joerg Vehlow <joerg.vehlow@aox-tech.de>
+
+TST_TESTFUNC=do_test
+
+TST_TIMEOUT=1
+. tst_test.sh
+
+do_test()
+{
+	tst_res TINFO "Start"
+    sleep 5
+    tst_res TFAIL "End"
+}
+
+do_cleanup()
+{
+    tst_res TINFO "cleanup"
+}
+
+tst_run
-- 
2.25.1

[LTP] [PATCH v2 2/2] shell: Prevent orphan timeout sleep processes

[Joerg Vehlow]

From: Joerg Vehlow <joerg.vehlow@aox-tech.de>

The implementation of the timeout handling failed to terminate the sleep
process, because the command "sleep $sec && _tst_kill_test &" spawns two
processes: A shell, that is used to execute the sleep and after sleep
terminates it executes _tst_kill_test. The pid stored in $! is the pid of
the shell process.
When the test finished, the timeout process is supposed to be killed, but
only the shell process is killed, not the sleep. If the output of the test
is piped somewhere else, the pipe stays open, until the sleep finished,
because it still has stdout open.
Additionally, if a lot of short tests with high timeouts are executed,
a lot of sleep processes will linger around.

Co-authored-by: Li Wang <liwang@redhat.com>
Signed-off-by: Joerg Vehlow <joerg.vehlow@aox-tech.de>
---
 testcases/lib/tst_test.sh | 30 +++++++++++++++++++++---------
 1 file changed, 21 insertions(+), 9 deletions(-)

diff --git a/testcases/lib/tst_test.sh b/testcases/lib/tst_test.sh
index 951518785..7ceddff04 100644
--- a/testcases/lib/tst_test.sh
+++ b/testcases/lib/tst_test.sh
@@ -23,14 +23,6 @@ export TST_LIB_LOADED=1
 # default trap function
 trap "tst_brk TBROK 'test interrupted or timed out'" INT
 
-_tst_cleanup_timer()
-{
-	if [ -n "$_tst_setup_timer_pid" ]; then
-		kill $_tst_setup_timer_pid 2>/dev/null
-		wait $_tst_setup_timer_pid 2>/dev/null
-	fi
-}
-
 _tst_do_exit()
 {
 	local ret=0
@@ -463,6 +455,25 @@ _tst_kill_test()
 	fi
 }
 
+_tst_cleanup_timer()
+{
+	if [ -n "$_tst_setup_timer_pid" ]; then
+		kill -TERM $_tst_setup_timer_pid 2>/dev/null
+		wait $_tst_setup_timer_pid 2>/dev/null
+	fi
+}
+
+_tst_timeout_process()
+{
+	local sleep_pid
+
+	sleep $sec &
+	sleep_pid=$!
+	#trap "kill $sleep_pid; exit" TERM
+	wait $sleep_pid
+	_tst_kill_test
+}
+
 _tst_setup_timer()
 {
 	TST_TIMEOUT=${TST_TIMEOUT:-300}
@@ -486,7 +497,8 @@ _tst_setup_timer()
 	tst_res TINFO "timeout per run is ${h}h ${m}m ${s}s"
 
 	_tst_cleanup_timer
-	sleep $sec && _tst_kill_test &
+
+	_tst_timeout_process &
 
 	_tst_setup_timer_pid=$!
 }
-- 
2.25.1

[LTP] [PATCH v2 2/2] shell: Prevent orphan timeout sleep processes

[Li Wang]

Hi Joerg,

Reviewed-by: Li Wang <liwang@redhat.com>

The patchset looks good except for few minor issues, we can help fix
them when merging.

--- a/lib/newlib_tests/shell/timeout03.sh
+++ b/lib/newlib_tests/shell/timeout03.sh
@@ -32,7 +32,7 @@ do_test()
 {
        tst_res TINFO "testing killing test after TST_TIMEOUT"

-       tst_sleep 2
+       sleep 2
        tst_res TFAIL "test: running after TST_TIMEOUT"
 }

@@ -40,7 +40,7 @@ cleanup()
 {
        tst_res TPASS "test run cleanup after timeout"

-       tst_sleep 15 # must be higher than wait time in _tst_kill_test
+       sleep 15 # must be higher than wait time in _tst_kill_test
        tst_res TFAIL "cleanup: running after TST_TIMEOUT"
 }

diff --git a/lib/newlib_tests/shell/timeout04.sh
b/lib/newlib_tests/shell/timeout04.sh
index 0a6ba053c..c702905f3 100755
--- a/lib/newlib_tests/shell/timeout04.sh
+++ b/lib/newlib_tests/shell/timeout04.sh
@@ -9,7 +9,7 @@ TST_TIMEOUT=1

 do_test()
 {
-       tst_res TINFO "Start"
+    tst_res TINFO "Start"
     sleep 5
     tst_res TFAIL "End"
 }
diff --git a/testcases/lib/tst_test.sh b/testcases/lib/tst_test.sh
index 7ceddff04..ed2699175 100644
--- a/testcases/lib/tst_test.sh
+++ b/testcases/lib/tst_test.sh
@@ -469,7 +469,7 @@ _tst_timeout_process()

        sleep $sec &
        sleep_pid=$!
-       #trap "kill $sleep_pid; exit" TERM
+       trap "kill $sleep_pid; exit" TERM
        wait $sleep_pid
        _tst_kill_test
 }


================
(This below is not related to your patches)

But there is another issue I found that the timeout03 can NOT
be killed after timed out in calling cleanup(), the reason is
tst_brk stop the _tst_kill_test running in the background so that
it does not output as what we expected:

# timeout03 1 TINFO: timeout per run is 0h 0m 1s
# timeout03 1 TINFO: testing killing test after TST_TIMEOUT
# timeout03 1 TBROK: Test timeouted, sending SIGINT! If you are
running on slow machine, try exporting LTP_TIMEOUT_MUL > 1
# timeout03 1 TBROK: test interrupted or timed out
# timeout03 1 TPASS: test run cleanup after timeout
# timeout03 1 TINFO: Test is still running, waiting 10s
# timeout03 1 TINFO: Test is still running, waiting 9s
# timeout03 1 TINFO: Test is still running, waiting 8s
# timeout03 1 TINFO: Test is still running, waiting 7s
# timeout03 1 TINFO: Test is still running, waiting 6s
# timeout03 1 TINFO: Test is still running, waiting 5s
# timeout03 1 TINFO: Test is still running, waiting 4s
# timeout03 1 TINFO: Test is still running, waiting 3s
# timeout03 1 TINFO: Test is still running, waiting 2s
# timeout03 1 TINFO: Test is still running, waiting 1s
# timeout03 1 TBROK: Test still running, sending SIGKILL
# Killed


--
Regards,
Li Wang

[LTP] [PATCH v2 2/2] shell: Prevent orphan timeout sleep processes

[Petr Vorel]

Hi Li, Joerg,

thanks both for your work!

> +++ b/lib/newlib_tests/shell/timeout03.sh
> @@ -32,7 +32,7 @@ do_test()
>  {
>         tst_res TINFO "testing killing test after TST_TIMEOUT"

> -       tst_sleep 2
> +       sleep 2
+1
Although tst_test.sh has many LTP custom binary dependencies I agree to use
simple sleep for seconds.

>         tst_res TFAIL "test: running after TST_TIMEOUT"
>  }

> @@ -40,7 +40,7 @@ cleanup()
>  {
>         tst_res TPASS "test run cleanup after timeout"

> -       tst_sleep 15 # must be higher than wait time in _tst_kill_test
> +       sleep 15 # must be higher than wait time in _tst_kill_test
and here.
>         tst_res TFAIL "cleanup: running after TST_TIMEOUT"
>  }

> diff --git a/lib/newlib_tests/shell/timeout04.sh
> b/lib/newlib_tests/shell/timeout04.sh
> index 0a6ba053c..c702905f3 100755
> --- a/lib/newlib_tests/shell/timeout04.sh
> +++ b/lib/newlib_tests/shell/timeout04.sh
> @@ -9,7 +9,7 @@ TST_TIMEOUT=1

>  do_test()
>  {
> -       tst_res TINFO "Start"
> +    tst_res TINFO "Start"
>      sleep 5
>      tst_res TFAIL "End"
>  }
> diff --git a/testcases/lib/tst_test.sh b/testcases/lib/tst_test.sh
> index 7ceddff04..ed2699175 100644
> --- a/testcases/lib/tst_test.sh
> +++ b/testcases/lib/tst_test.sh
> @@ -469,7 +469,7 @@ _tst_timeout_process()

>         sleep $sec &
>         sleep_pid=$!
> -       #trap "kill $sleep_pid; exit" TERM
> +       trap "kill $sleep_pid; exit" TERM
I guess trap use is needed, and commented out for testing.

>         wait $sleep_pid
>         _tst_kill_test
>  }


> ================
> (This below is not related to your patches)

> But there is another issue I found that the timeout03 can NOT
> be killed after timed out in calling cleanup(), the reason is
> tst_brk stop the _tst_kill_test running in the background so that
> it does not output as what we expected:
Good catch, I'll try to have a look as well.

Kind regards,
Petr

> # timeout03 1 TINFO: timeout per run is 0h 0m 1s
> # timeout03 1 TINFO: testing killing test after TST_TIMEOUT
> # timeout03 1 TBROK: Test timeouted, sending SIGINT! If you are
> running on slow machine, try exporting LTP_TIMEOUT_MUL > 1
> # timeout03 1 TBROK: test interrupted or timed out
> # timeout03 1 TPASS: test run cleanup after timeout
> # timeout03 1 TINFO: Test is still running, waiting 10s
> # timeout03 1 TINFO: Test is still running, waiting 9s
> # timeout03 1 TINFO: Test is still running, waiting 8s
> # timeout03 1 TINFO: Test is still running, waiting 7s
> # timeout03 1 TINFO: Test is still running, waiting 6s
> # timeout03 1 TINFO: Test is still running, waiting 5s
> # timeout03 1 TINFO: Test is still running, waiting 4s
> # timeout03 1 TINFO: Test is still running, waiting 3s
> # timeout03 1 TINFO: Test is still running, waiting 2s
> # timeout03 1 TINFO: Test is still running, waiting 1s
> # timeout03 1 TBROK: Test still running, sending SIGKILL
> # Killed

[LTP] [PATCH v2 2/2] shell: Prevent orphan timeout sleep processes

[Li Wang]

> > ================
> > (This below is not related to your patches)
>
> > But there is another issue I found that the timeout03 can NOT
> > be killed after timed out in calling cleanup(), the reason is
> > tst_brk stop the _tst_kill_test running in the background so that
> > it does not output as what we expected:
> Good catch, I'll try to have a look as well.

The simplest way I can think of is to let _tst_kill_test ignores
the TERM and INT signals. If you agree to this, we can fix it in
a separate patch:).

--- a/testcases/lib/tst_test.sh
+++ b/testcases/lib/tst_test.sh
@@ -439,6 +439,8 @@ _tst_kill_test()
 {
        local i=10

+       trap " " TERM INT
+
        tst_res TBROK "Test timeouted, sending SIGINT! If you are
running on slow machine, try exporting LTP_TIMEOUT_MUL > 1"
        kill -INT -$pid
        tst_sleep 100ms


-- 
Regards,
Li Wang

[LTP] [PATCH v2 2/2] shell: Prevent orphan timeout sleep processes

[Petr Vorel]

Hi Li,

> > > But there is another issue I found that the timeout03 can NOT
> > > be killed after timed out in calling cleanup(), the reason is
> > > tst_brk stop the _tst_kill_test running in the background so that
> > > it does not output as what we expected:
> > Good catch, I'll try to have a look as well.

> The simplest way I can think of is to let _tst_kill_test ignores
> the TERM and INT signals. If you agree to this, we can fix it in
> a separate patch:).

> --- a/testcases/lib/tst_test.sh
> +++ b/testcases/lib/tst_test.sh
> @@ -439,6 +439,8 @@ _tst_kill_test()
>  {
>         local i=10

> +       trap " " TERM INT
Acked-by: Petr Vorel <pvorel@suse.cz>

Thanks!

BTW I'm surprised " " works, I'd expect : would have to be used.

Kind regards,
Petr

[LTP] [PATCH v2 2/2] shell: Prevent orphan timeout sleep processes

[Li Wang]

> > --- a/testcases/lib/tst_test.sh
> > +++ b/testcases/lib/tst_test.sh
> > @@ -439,6 +439,8 @@ _tst_kill_test()
> >  {
> >         local i=10
>
> > +       trap " " TERM INT

Seems no need to ignore the SIGTERM, because it only sends in
the early (before timeout) phase, the _tst_kill_test has no chance
to catch a SIGTERM.

> Acked-by: Petr Vorel <pvorel@suse.cz>

Thanks for the review! I will send a patch for it.

>
> Thanks!
>
> BTW I'm surprised " " works, I'd expect : would have to be used.

" " or '' define none string makes it ignore signals.

-- 
Regards,
Li Wang