[PATCH 0/2] selftests/harness: Handle timeouts cleanly

[PATCH 0/2] selftests/harness: Handle timeouts cleanly

[Kees Cook]

When a selftest would timeout before, the program would just fall over
and no accounting of failures would be reported (i.e. it would result in
an incomplete TAP report). Instead, add an explicit SIGALRM handler to
cleanly catch and report the timeout.

Before:

        [==========] Running 2 tests from 2 test cases.
        [ RUN      ] timeout.finish
        [       OK ] timeout.finish
        [ RUN      ] timeout.too_long
        Alarm clock

After:

        [==========] Running 2 tests from 2 test cases.
        [ RUN      ] timeout.finish
        [       OK ] timeout.finish
        [ RUN      ] timeout.too_long
        timeout.too_long: Test terminated by timeout
        [     FAIL ] timeout.too_long
        [==========] 1 / 2 tests passed.
        [  FAILED  ]

-Kees

Kees Cook (2):
  selftests/seccomp: Move test child waiting logic
  selftests/harness: Handle timeouts cleanly

 tools/testing/selftests/kselftest_harness.h | 144 ++++++++++++++------
 1 file changed, 99 insertions(+), 45 deletions(-)

-- 
2.20.1

[PATCH 1/2] selftests/seccomp: Move test child waiting logic

[Kees Cook]

In order to better handle timeout failures, rearrange the child waiting
logic into a separate function. This is mostly a copy/paste with an
indentation change. To handle pid tracking, a new field is added for
the child pid. Also move the alarm() pairing into the function.

Signed-off-by: Kees Cook <keescook@chromium.org>
---
 tools/testing/selftests/kselftest_harness.h | 93 +++++++++++----------
 1 file changed, 49 insertions(+), 44 deletions(-)

diff --git a/tools/testing/selftests/kselftest_harness.h b/tools/testing/selftests/kselftest_harness.h
index 5336b26506ab..c7b67e379219 100644
--- a/tools/testing/selftests/kselftest_harness.h
+++ b/tools/testing/selftests/kselftest_harness.h
@@ -635,6 +635,7 @@
 struct __test_metadata {
 	const char *name;
 	void (*fn)(struct __test_metadata *);
+	pid_t pid;	/* pid of test when being run */
 	int termsig;
 	int passed;
 	int trigger; /* extra handler after the evaluation */
@@ -695,64 +696,68 @@ static inline int __bail(int for_realz, bool no_print, __u8 step)
 	return 0;
 }
 
-void __run_test(struct __test_metadata *t)
+void __wait_for_test(struct __test_metadata *t)
 {
-	pid_t child_pid;
 	int status;
 
+	alarm(t->timeout);
+	waitpid(t->pid, &status, 0);
+	alarm(0);
+
+	if (WIFEXITED(status)) {
+		t->passed = t->termsig == -1 ? !WEXITSTATUS(status) : 0;
+		if (t->termsig != -1) {
+			fprintf(TH_LOG_STREAM,
+				"%s: Test exited normally "
+				"instead of by signal (code: %d)\n",
+				t->name,
+				WEXITSTATUS(status));
+		} else if (!t->passed) {
+			fprintf(TH_LOG_STREAM,
+				"%s: Test failed at step #%d\n",
+				t->name,
+				WEXITSTATUS(status));
+		}
+	} else if (WIFSIGNALED(status)) {
+		t->passed = 0;
+		if (WTERMSIG(status) == SIGABRT) {
+			fprintf(TH_LOG_STREAM,
+				"%s: Test terminated by assertion\n",
+				t->name);
+		} else if (WTERMSIG(status) == t->termsig) {
+			t->passed = 1;
+		} else {
+			fprintf(TH_LOG_STREAM,
+				"%s: Test terminated unexpectedly "
+				"by signal %d\n",
+				t->name,
+				WTERMSIG(status));
+		}
+	} else {
+		fprintf(TH_LOG_STREAM,
+			"%s: Test ended in some other way [%u]\n",
+			t->name,
+			status);
+	}
+}
+
+void __run_test(struct __test_metadata *t)
+{
 	t->passed = 1;
 	t->trigger = 0;
 	printf("[ RUN      ] %s\n", t->name);
-	alarm(t->timeout);
-	child_pid = fork();
-	if (child_pid < 0) {
+	t->pid = fork();
+	if (t->pid < 0) {
 		printf("ERROR SPAWNING TEST CHILD\n");
 		t->passed = 0;
-	} else if (child_pid == 0) {
+	} else if (t->pid == 0) {
 		t->fn(t);
 		/* return the step that failed or 0 */
 		_exit(t->passed ? 0 : t->step);
 	} else {
-		/* TODO(wad) add timeout support. */
-		waitpid(child_pid, &status, 0);
-		if (WIFEXITED(status)) {
-			t->passed = t->termsig == -1 ? !WEXITSTATUS(status) : 0;
-			if (t->termsig != -1) {
-				fprintf(TH_LOG_STREAM,
-					"%s: Test exited normally "
-					"instead of by signal (code: %d)\n",
-					t->name,
-					WEXITSTATUS(status));
-			} else if (!t->passed) {
-				fprintf(TH_LOG_STREAM,
-					"%s: Test failed at step #%d\n",
-					t->name,
-					WEXITSTATUS(status));
-			}
-		} else if (WIFSIGNALED(status)) {
-			t->passed = 0;
-			if (WTERMSIG(status) == SIGABRT) {
-				fprintf(TH_LOG_STREAM,
-					"%s: Test terminated by assertion\n",
-					t->name);
-			} else if (WTERMSIG(status) == t->termsig) {
-				t->passed = 1;
-			} else {
-				fprintf(TH_LOG_STREAM,
-					"%s: Test terminated unexpectedly "
-					"by signal %d\n",
-					t->name,
-					WTERMSIG(status));
-			}
-		} else {
-			fprintf(TH_LOG_STREAM,
-				"%s: Test ended in some other way [%u]\n",
-				t->name,
-				status);
-		}
+		__wait_for_test(t);
 	}
 	printf("[     %4s ] %s\n", (t->passed ? "OK" : "FAIL"), t->name);
-	alarm(0);
 }
 
 static int test_harness_run(int __attribute__((unused)) argc,
-- 
2.20.1

Re: [PATCH 1/2] selftests/seccomp: Move test child waiting logic

[Kees Cook]

On Wed, Mar 11, 2020 at 02:17:32PM -0700, Kees Cook wrote:
> ---
>  tools/testing/selftests/kselftest_harness.h | 93 +++++++++++----------
>  1 file changed, 49 insertions(+), 44 deletions(-)

Hrm, the Subject prefix is wrong here. It should be
"selftests/harness:". I can send a v2, or if everything is okay, can you
fix this up in your tree?

-Kees

-- 
Kees Cook

[PATCH 2/2] selftests/harness: Handle timeouts cleanly

[Kees Cook]

When a selftest would timeout before, the program would just fall over
and no accounting of failures would be reported (i.e. it would result in
an incomplete TAP report). Instead, add an explicit SIGALRM handler to
cleanly catch and report the timeout.

Before:

	[==========] Running 2 tests from 2 test cases.
	[ RUN      ] timeout.finish
	[       OK ] timeout.finish
	[ RUN      ] timeout.too_long
	Alarm clock

After:

	[==========] Running 2 tests from 2 test cases.
	[ RUN      ] timeout.finish
	[       OK ] timeout.finish
	[ RUN      ] timeout.too_long
	timeout.too_long: Test terminated by timeout
	[     FAIL ] timeout.too_long
	[==========] 1 / 2 tests passed.
	[  FAILED  ]

Signed-off-by: Kees Cook <keescook@chromium.org>
---
 tools/testing/selftests/kselftest_harness.h | 53 ++++++++++++++++++++-
 1 file changed, 51 insertions(+), 2 deletions(-)

diff --git a/tools/testing/selftests/kselftest_harness.h b/tools/testing/selftests/kselftest_harness.h
index c7b67e379219..2902f6a78f8a 100644
--- a/tools/testing/selftests/kselftest_harness.h
+++ b/tools/testing/selftests/kselftest_harness.h
@@ -639,7 +639,8 @@ struct __test_metadata {
 	int termsig;
 	int passed;
 	int trigger; /* extra handler after the evaluation */
-	int timeout;
+	int timeout;	/* seconds to wait for test timeout */
+	bool timed_out;	/* did this test timeout instead of exiting? */
 	__u8 step;
 	bool no_print; /* manual trigger when TH_LOG_STREAM is not available */
 	struct __test_metadata *prev, *next;
@@ -696,15 +697,63 @@ static inline int __bail(int for_realz, bool no_print, __u8 step)
 	return 0;
 }
 
+struct __test_metadata *__active_test;
+static void __timeout_handler(int sig, siginfo_t *info, void *ucontext)
+{
+	struct __test_metadata *t = __active_test;
+
+	/* Sanity check handler execution environment. */
+	if (!t) {
+		fprintf(TH_LOG_STREAM,
+			"no active test in SIGARLM handler!?\n");
+		abort();
+	}
+	if (sig != SIGALRM || sig != info->si_signo) {
+		fprintf(TH_LOG_STREAM,
+			"%s: SIGALRM handler caught signal %d!?\n",
+			t->name, sig != SIGALRM ? sig : info->si_signo);
+		abort();
+	}
+
+	t->timed_out = true;
+	kill(t->pid, SIGKILL);
+}
+
 void __wait_for_test(struct __test_metadata *t)
 {
+	struct sigaction action = {
+		.sa_sigaction = __timeout_handler,
+		.sa_flags = SA_SIGINFO,
+	};
+	struct sigaction saved_action;
 	int status;
 
+	if (sigaction(SIGALRM, &action, &saved_action)) {
+		t->passed = 0;
+		fprintf(TH_LOG_STREAM,
+			"%s: unable to install SIGARLM handler\n",
+			t->name);
+		return;
+	}
+	__active_test = t;
+	t->timed_out = false;
 	alarm(t->timeout);
 	waitpid(t->pid, &status, 0);
 	alarm(0);
+	if (sigaction(SIGALRM, &saved_action, NULL)) {
+		t->passed = 0;
+		fprintf(TH_LOG_STREAM,
+			"%s: unable to uninstall SIGARLM handler\n",
+			t->name);
+		return;
+	}
+	__active_test = NULL;
 
-	if (WIFEXITED(status)) {
+	if (t->timed_out) {
+		t->passed = 0;
+		fprintf(TH_LOG_STREAM,
+			"%s: Test terminated by timeout\n", t->name);
+	} else if (WIFEXITED(status)) {
 		t->passed = t->termsig == -1 ? !WEXITSTATUS(status) : 0;
 		if (t->termsig != -1) {
 			fprintf(TH_LOG_STREAM,
-- 
2.20.1

Re: [PATCH 0/2] selftests/harness: Handle timeouts cleanly

[shuah]

Hi Kees,

On 3/11/20 3:17 PM, Kees Cook wrote:
> When a selftest would timeout before, the program would just fall over
> and no accounting of failures would be reported (i.e. it would result in
> an incomplete TAP report). Instead, add an explicit SIGALRM handler to
> cleanly catch and report the timeout.
> 
> Before:
> 
>          [==========] Running 2 tests from 2 test cases.
>          [ RUN      ] timeout.finish
>          [       OK ] timeout.finish
>          [ RUN      ] timeout.too_long
>          Alarm clock
> 
> After:
> 
>          [==========] Running 2 tests from 2 test cases.
>          [ RUN      ] timeout.finish
>          [       OK ] timeout.finish
>          [ RUN      ] timeout.too_long
>          timeout.too_long: Test terminated by timeout
>          [     FAIL ] timeout.too_long
>          [==========] 1 / 2 tests passed.
>          [  FAILED  ]
> 

This is good info. to capturein the commit logs for the patches.
Please add them and send v2. You can also fix the subject prefix
at the same time :)

thanks,
-- Shuah

Re: [PATCH 0/2] selftests/harness: Handle timeouts cleanly

[Kees Cook]

On Fri, Mar 13, 2020 at 11:25:58AM -0600, shuah wrote:
> Hi Kees,
> 
> On 3/11/20 3:17 PM, Kees Cook wrote:
> > When a selftest would timeout before, the program would just fall over
> > and no accounting of failures would be reported (i.e. it would result in
> > an incomplete TAP report). Instead, add an explicit SIGALRM handler to
> > cleanly catch and report the timeout.
> > 
> > Before:
> > 
> >          [==========] Running 2 tests from 2 test cases.
> >          [ RUN      ] timeout.finish
> >          [       OK ] timeout.finish
> >          [ RUN      ] timeout.too_long
> >          Alarm clock
> > 
> > After:
> > 
> >          [==========] Running 2 tests from 2 test cases.
> >          [ RUN      ] timeout.finish
> >          [       OK ] timeout.finish
> >          [ RUN      ] timeout.too_long
> >          timeout.too_long: Test terminated by timeout
> >          [     FAIL ] timeout.too_long
> >          [==========] 1 / 2 tests passed.
> >          [  FAILED  ]
> > 
> 
> This is good info. to capturein the commit logs for the patches.

The cover letter is an exact copy of patch 2's commit log. :)

> Please add them and send v2. You can also fix the subject prefix
> at the same time :)

I'll resend a v2 with fixed prefix regardless.

-- 
Kees Cook