This should fix test regressions seen when running under unbuffered output. Additionally, fixes are added for the missing flushed output in the timers test which become obvious without unbuffered output.
-Kees
Kees Cook (2): selftests: Remove forced unbuffering for test running selftests/timers: Add missing fflush(stdout) calls
tools/testing/selftests/kselftest/runner.sh | 12 +----------- tools/testing/selftests/timers/adjtick.c | 1 + tools/testing/selftests/timers/leapcrash.c | 1 + tools/testing/selftests/timers/mqueue-lat.c | 1 + tools/testing/selftests/timers/nanosleep.c | 1 + tools/testing/selftests/timers/nsleep-lat.c | 1 + tools/testing/selftests/timers/raw_skew.c | 1 + tools/testing/selftests/timers/set-tai.c | 1 + tools/testing/selftests/timers/set-tz.c | 2 ++ tools/testing/selftests/timers/threadtest.c | 1 + tools/testing/selftests/timers/valid-adjtimex.c | 2 ++ 11 files changed, 13 insertions(+), 11 deletions(-)
As it turns out, the "stdbuf" command will actually force all subprocesses into unbuffered output, and some implementations of "echo" turn into single-character writes, which utterly wrecks writes to /sys and /proc files.
Instead, drop the "stdbuf" usage, and for any tests that want explicit flushing between newlines, they'll have to add "fflush(stdout);" as needed.
Reported-by: Takashi Iwai tiwai@suse.de Fixes: 5c069b6dedef ("selftests: Move test output to diagnostic lines") Signed-off-by: Kees Cook keescook@chromium.org --- tools/testing/selftests/kselftest/runner.sh | 12 +----------- 1 file changed, 1 insertion(+), 11 deletions(-)
diff --git a/tools/testing/selftests/kselftest/runner.sh b/tools/testing/selftests/kselftest/runner.sh index eff3ee303d0d..00c9020bdda8 100644 --- a/tools/testing/selftests/kselftest/runner.sh +++ b/tools/testing/selftests/kselftest/runner.sh @@ -24,16 +24,6 @@ tap_prefix() fi }
-# If stdbuf is unavailable, we must fall back to line-at-a-time piping. -tap_unbuffer() -{ - if ! which stdbuf >/dev/null ; then - "$@" - else - stdbuf -i0 -o0 -e0 "$@" - fi -} - run_one() { DIR="$1" @@ -54,7 +44,7 @@ run_one() echo "not ok $test_num $TEST_HDR_MSG" else cd `dirname $TEST` > /dev/null - (((((tap_unbuffer ./$BASENAME_TEST 2>&1; echo $? >&3) | + (((((./$BASENAME_TEST 2>&1; echo $? >&3) | tap_prefix >&4) 3>&1) | (read xs; exit $xs)) 4>>"$logfile" && echo "ok $test_num $TEST_HDR_MSG") ||
On Tue, 21 May 2019 00:37:48 +0200, Kees Cook wrote:
As it turns out, the "stdbuf" command will actually force all subprocesses into unbuffered output, and some implementations of "echo" turn into single-character writes, which utterly wrecks writes to /sys and /proc files.
Instead, drop the "stdbuf" usage, and for any tests that want explicit flushing between newlines, they'll have to add "fflush(stdout);" as needed.
Reported-by: Takashi Iwai tiwai@suse.de Fixes: 5c069b6dedef ("selftests: Move test output to diagnostic lines") Signed-off-by: Kees Cook keescook@chromium.org
Tested-by: Takashi Iwai tiwai@suse.de
BTW, this might be specific to shell invocation. As in the original discussion thread, it starts working when I replace "echo" with "/usr/bin/echo".
Still it's not easy to control in a script itself, so dropping the unbuffered mode is certainly safer, yes.
Thanks!
Takashi
tools/testing/selftests/kselftest/runner.sh | 12 +----------- 1 file changed, 1 insertion(+), 11 deletions(-)
diff --git a/tools/testing/selftests/kselftest/runner.sh b/tools/testing/selftests/kselftest/runner.sh index eff3ee303d0d..00c9020bdda8 100644 --- a/tools/testing/selftests/kselftest/runner.sh +++ b/tools/testing/selftests/kselftest/runner.sh @@ -24,16 +24,6 @@ tap_prefix() fi } -# If stdbuf is unavailable, we must fall back to line-at-a-time piping. -tap_unbuffer() -{
- if ! which stdbuf >/dev/null ; then
"$@"- else
stdbuf -i0 -o0 -e0 "$@"- fi
-}
run_one() { DIR="$1" @@ -54,7 +44,7 @@ run_one() echo "not ok $test_num $TEST_HDR_MSG" else cd `dirname $TEST` > /dev/null
(((((tap_unbuffer ./$BASENAME_TEST 2>&1; echo $? >&3) |
(((((./$BASENAME_TEST 2>&1; echo $? >&3) | tap_prefix >&4) 3>&1) | (read xs; exit $xs)) 4>>"$logfile" &&-- 2.17.1
On 5/20/19 11:21 PM, Takashi Iwai wrote:
On Tue, 21 May 2019 00:37:48 +0200, Kees Cook wrote:
As it turns out, the "stdbuf" command will actually force all subprocesses into unbuffered output, and some implementations of "echo" turn into single-character writes, which utterly wrecks writes to /sys and /proc files.
Instead, drop the "stdbuf" usage, and for any tests that want explicit flushing between newlines, they'll have to add "fflush(stdout);" as needed.
Reported-by: Takashi Iwai tiwai@suse.de Fixes: 5c069b6dedef ("selftests: Move test output to diagnostic lines") Signed-off-by: Kees Cook keescook@chromium.org
Tested-by: Takashi Iwai tiwai@suse.de
BTW, this might be specific to shell invocation. As in the original discussion thread, it starts working when I replace "echo" with "/usr/bin/echo".
Still it's not easy to control in a script itself, so dropping the unbuffered mode is certainly safer, yes.
Thanks!
Thank you both.
I will get this in for next rc.
-- Shuah
When running under a pipe, some timer tests would not report output in real-time because stdout flushes were missing after printf()s that lacked a newline. This adds them to restore real-time status output that humans can enjoy.
Signed-off-by: Kees Cook keescook@chromium.org --- tools/testing/selftests/timers/adjtick.c | 1 + tools/testing/selftests/timers/leapcrash.c | 1 + tools/testing/selftests/timers/mqueue-lat.c | 1 + tools/testing/selftests/timers/nanosleep.c | 1 + tools/testing/selftests/timers/nsleep-lat.c | 1 + tools/testing/selftests/timers/raw_skew.c | 1 + tools/testing/selftests/timers/set-tai.c | 1 + tools/testing/selftests/timers/set-tz.c | 2 ++ tools/testing/selftests/timers/threadtest.c | 1 + tools/testing/selftests/timers/valid-adjtimex.c | 2 ++ 10 files changed, 12 insertions(+)
diff --git a/tools/testing/selftests/timers/adjtick.c b/tools/testing/selftests/timers/adjtick.c index 0caca3a06bd2..54d8d87f36b3 100644 --- a/tools/testing/selftests/timers/adjtick.c +++ b/tools/testing/selftests/timers/adjtick.c @@ -136,6 +136,7 @@ int check_tick_adj(long tickval)
eppm = get_ppm_drift(); printf("%lld usec, %lld ppm", systick + (systick * eppm / MILLION), eppm); + fflush(stdout);
tx1.modes = 0; adjtimex(&tx1); diff --git a/tools/testing/selftests/timers/leapcrash.c b/tools/testing/selftests/timers/leapcrash.c index 830c462f605d..dc80728ed191 100644 --- a/tools/testing/selftests/timers/leapcrash.c +++ b/tools/testing/selftests/timers/leapcrash.c @@ -101,6 +101,7 @@ int main(void) } clear_time_state(); printf("."); + fflush(stdout); } printf("[OK]\n"); return ksft_exit_pass(); diff --git a/tools/testing/selftests/timers/mqueue-lat.c b/tools/testing/selftests/timers/mqueue-lat.c index 1867db5d6f5e..7916cf5cc6ff 100644 --- a/tools/testing/selftests/timers/mqueue-lat.c +++ b/tools/testing/selftests/timers/mqueue-lat.c @@ -102,6 +102,7 @@ int main(int argc, char **argv) int ret;
printf("Mqueue latency : "); + fflush(stdout);
ret = mqueue_lat_test(); if (ret < 0) { diff --git a/tools/testing/selftests/timers/nanosleep.c b/tools/testing/selftests/timers/nanosleep.c index 8adb0bb51d4d..71b5441c2fd9 100644 --- a/tools/testing/selftests/timers/nanosleep.c +++ b/tools/testing/selftests/timers/nanosleep.c @@ -142,6 +142,7 @@ int main(int argc, char **argv) continue;
printf("Nanosleep %-31s ", clockstring(clockid)); + fflush(stdout);
length = 10; while (length <= (NSEC_PER_SEC * 10)) { diff --git a/tools/testing/selftests/timers/nsleep-lat.c b/tools/testing/selftests/timers/nsleep-lat.c index c3c3dc10db17..eb3e79ed7b4a 100644 --- a/tools/testing/selftests/timers/nsleep-lat.c +++ b/tools/testing/selftests/timers/nsleep-lat.c @@ -155,6 +155,7 @@ int main(int argc, char **argv) continue;
printf("nsleep latency %-26s ", clockstring(clockid)); + fflush(stdout);
length = 10; while (length <= (NSEC_PER_SEC * 10)) { diff --git a/tools/testing/selftests/timers/raw_skew.c b/tools/testing/selftests/timers/raw_skew.c index dcf73c5dab6e..b41d8dd0c40c 100644 --- a/tools/testing/selftests/timers/raw_skew.c +++ b/tools/testing/selftests/timers/raw_skew.c @@ -112,6 +112,7 @@ int main(int argv, char **argc) printf("WARNING: ADJ_OFFSET in progress, this will cause inaccurate results\n");
printf("Estimating clock drift: "); + fflush(stdout); sleep(120);
get_monotonic_and_raw(&mon, &raw); diff --git a/tools/testing/selftests/timers/set-tai.c b/tools/testing/selftests/timers/set-tai.c index 70fed27d8fd3..8c4179ee2ca2 100644 --- a/tools/testing/selftests/timers/set-tai.c +++ b/tools/testing/selftests/timers/set-tai.c @@ -55,6 +55,7 @@ int main(int argc, char **argv) printf("tai offset started at %i\n", ret);
printf("Checking tai offsets can be properly set: "); + fflush(stdout); for (i = 1; i <= 60; i++) { ret = set_tai(i); ret = get_tai(); diff --git a/tools/testing/selftests/timers/set-tz.c b/tools/testing/selftests/timers/set-tz.c index 877fd5532fee..62bd33eb16f0 100644 --- a/tools/testing/selftests/timers/set-tz.c +++ b/tools/testing/selftests/timers/set-tz.c @@ -65,6 +65,7 @@ int main(int argc, char **argv) printf("tz_minuteswest started at %i, dst at %i\n", min, dst);
printf("Checking tz_minuteswest can be properly set: "); + fflush(stdout); for (i = -15*60; i < 15*60; i += 30) { ret = set_tz(i, dst); ret = get_tz_min(); @@ -76,6 +77,7 @@ int main(int argc, char **argv) printf("[OK]\n");
printf("Checking invalid tz_minuteswest values are caught: "); + fflush(stdout);
if (!set_tz(-15*60-1, dst)) { printf("[FAILED] %i didn't return failure!\n", -15*60-1); diff --git a/tools/testing/selftests/timers/threadtest.c b/tools/testing/selftests/timers/threadtest.c index 759c9c06f1a0..cf3e48919874 100644 --- a/tools/testing/selftests/timers/threadtest.c +++ b/tools/testing/selftests/timers/threadtest.c @@ -163,6 +163,7 @@ int main(int argc, char **argv) strftime(buf, 255, "%a, %d %b %Y %T %z", localtime(&start)); printf("%s\n", buf); printf("Testing consistency with %i threads for %ld seconds: ", thread_count, runtime); + fflush(stdout);
/* spawn */ for (i = 0; i < thread_count; i++) diff --git a/tools/testing/selftests/timers/valid-adjtimex.c b/tools/testing/selftests/timers/valid-adjtimex.c index d9d3ab93b31a..5397de708d3c 100644 --- a/tools/testing/selftests/timers/valid-adjtimex.c +++ b/tools/testing/selftests/timers/valid-adjtimex.c @@ -123,6 +123,7 @@ int validate_freq(void) /* Set the leap second insert flag */
printf("Testing ADJ_FREQ... "); + fflush(stdout); for (i = 0; i < NUM_FREQ_VALID; i++) { tx.modes = ADJ_FREQUENCY; tx.freq = valid_freq[i]; @@ -250,6 +251,7 @@ int set_bad_offset(long sec, long usec, int use_nano) int validate_set_offset(void) { printf("Testing ADJ_SETOFFSET... "); + fflush(stdout);
/* Test valid values */ if (set_offset(NSEC_PER_SEC - 1, 1))
linux-kselftest-mirror@lists.linaro.org
-
Kees Cook -
shuah -
Takashi Iwai