* [PATCH v2 0/2] selftests/harness: Handle timeouts cleanly
@ 2020-03-13 23:12 Kees Cook
2020-03-13 23:12 ` [PATCH v2 1/2] selftests/harness: Move test child waiting logic Kees Cook
2020-03-13 23:12 ` [PATCH v2 2/2] selftests/harness: Handle timeouts cleanly Kees Cook
0 siblings, 2 replies; 5+ messages in thread
From: Kees Cook @ 2020-03-13 23:12 UTC (permalink / raw)
To: Shuah Khan
Cc: Kees Cook, Andy Lutomirski, Will Drewry, linux-kselftest, linux-kernel
Repeating patch 2/2's commit log:
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 ]
Thanks!
-Kees
v2:
- fix typo in subject prefix
v1: https://lore.kernel.org/lkml/20200311211733.21211-1-keescook@chromium.org
Kees Cook (2):
selftests/harness: 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
^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH v2 1/2] selftests/harness: Move test child waiting logic
2020-03-13 23:12 [PATCH v2 0/2] selftests/harness: Handle timeouts cleanly Kees Cook
@ 2020-03-13 23:12 ` Kees Cook
2020-03-23 18:08 ` shuah
2020-03-13 23:12 ` [PATCH v2 2/2] selftests/harness: Handle timeouts cleanly Kees Cook
1 sibling, 1 reply; 5+ messages in thread
From: Kees Cook @ 2020-03-13 23:12 UTC (permalink / raw)
To: Shuah Khan
Cc: Kees Cook, Andy Lutomirski, Will Drewry, linux-kselftest, linux-kernel
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH v2 2/2] selftests/harness: Handle timeouts cleanly
2020-03-13 23:12 [PATCH v2 0/2] selftests/harness: Handle timeouts cleanly Kees Cook
2020-03-13 23:12 ` [PATCH v2 1/2] selftests/harness: Move test child waiting logic Kees Cook
@ 2020-03-13 23:12 ` Kees Cook
1 sibling, 0 replies; 5+ messages in thread
From: Kees Cook @ 2020-03-13 23:12 UTC (permalink / raw)
To: Shuah Khan
Cc: Kees Cook, Andy Lutomirski, Will Drewry, linux-kselftest, linux-kernel
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH v2 1/2] selftests/harness: Move test child waiting logic
2020-03-13 23:12 ` [PATCH v2 1/2] selftests/harness: Move test child waiting logic Kees Cook
@ 2020-03-23 18:08 ` shuah
2020-03-23 19:23 ` Kees Cook
0 siblings, 1 reply; 5+ messages in thread
From: shuah @ 2020-03-23 18:08 UTC (permalink / raw)
To: Kees Cook
Cc: Andy Lutomirski, Will Drewry, linux-kselftest, linux-kernel, shuah
Hi Kees,
On 3/13/20 5:12 PM, Kees Cook wrote:
> 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>
Sorry for the delay. I was on vacation all of last week
and totally trying to stay away from checking email.
My commit scripts falied on checkpatch warnings.
A couple of comments below:
> ---
> 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));
This one isn't an error and gets printed to stderr? Except for
this one message, all other messages in this routine are indeed
errors. It makes sense to print this out to stdout instead.
> + } 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,
>
thanks,
-- Shuah
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH v2 1/2] selftests/harness: Move test child waiting logic
2020-03-23 18:08 ` shuah
@ 2020-03-23 19:23 ` Kees Cook
0 siblings, 0 replies; 5+ messages in thread
From: Kees Cook @ 2020-03-23 19:23 UTC (permalink / raw)
To: shuah; +Cc: Andy Lutomirski, Will Drewry, linux-kselftest, linux-kernel
On Mon, Mar 23, 2020 at 12:08:13PM -0600, shuah wrote:
> Hi Kees,
>
> On 3/13/20 5:12 PM, Kees Cook wrote:
> > 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>
>
> Sorry for the delay. I was on vacation all of last week
> and totally trying to stay away from checking email.
Indeed; that's what vacation is for! :)
> My commit scripts falied on checkpatch warnings.
All the macros in this file tend to anger checkpatch. ;)
>
> A couple of comments below:
>
>
> > ---
> > 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));
>
> This one isn't an error and gets printed to stderr? Except for
> this one message, all other messages in this routine are indeed
> errors. It makes sense to print this out to stdout instead.
No, this is an error. A signal was _expected_ in this case, but the
program exited without a signal. i.e. the test case failed, and the
error is reported to stderr.
(This portion, btw, is just moved from below.)
>
> > + } 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,
> >
>
> thanks,
> -- Shuah
Hopefully that clears it up. I don't see anything to change for a v2?
Did I miss anything?
Thanks!
-Kees
--
Kees Cook
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2020-03-23 19:23 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-03-13 23:12 [PATCH v2 0/2] selftests/harness: Handle timeouts cleanly Kees Cook
2020-03-13 23:12 ` [PATCH v2 1/2] selftests/harness: Move test child waiting logic Kees Cook
2020-03-23 18:08 ` shuah
2020-03-23 19:23 ` Kees Cook
2020-03-13 23:12 ` [PATCH v2 2/2] selftests/harness: Handle timeouts cleanly Kees Cook
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).