-----Original Message----- From: Kees Cook Sent: Sunday, June 14, 2020 12:18 PM To: David Gow davidgow@google.com Cc: Vitor Massaru Iha vitor@massaru.org; KUnit Development kunit-dev@googlegroups.com; Shuah Khan skhan@linuxfoundation.org; open list:KERNEL SELFTEST FRAMEWORK linux-kselftest@vger.kernel.org; Linux Kernel Mailing List linux-kernel@vger.kernel.org; Brendan Higgins brendanhiggins@google.com; linux-kernel-mentees@lists.linuxfoundation.org; linux@rasmusvillemoes.dk Subject: Re: RFC - kernel selftest result documentation (KTAP)
On Sat, Jun 13, 2020 at 02:51:17PM +0800, David Gow wrote:
On Sat, Jun 13, 2020 at 6:36 AM Kees Cook keescook@chromium.org wrote:
Regarding output:
[ 36.611358] TAP version 14 [ 36.611953] # Subtest: overflow [ 36.611954] 1..3 ... [ 36.622914] # overflow_calculation_test: s64: 21 arithmetic tests [ 36.624020] ok 1 - overflow_calculation_test ... [ 36.731096] # overflow_shift_test: ok: (s64)(0 << 63) == 0 [ 36.731840] ok 2 - overflow_shift_test ... [ 36.750294] kunit_try_catch: vmalloc: allocation failure: 18446744073709551615 bytes, mode:0xcc0(GFP_KERNEL),
nodemask=(null),cpuset=/,mems_allowed=0
... [ 36.805350] # overflow_allocation_test: devm_kzalloc detected saturation [ 36.807763] ok 3 - overflow_allocation_test [ 36.807765] ok 1 - overflow
A few things here....
Tim Bird has just sent out an RFC for a "KTAP" specification, which we'll hope to support in KUnit:
Ah-ha! Thanks for the heads-up. :)
kselftest/CY4PR13MB1175B804E31E502221BC8163FD830@CY4PR13MB1175.namprd13.prod.outlook.com/T/#u
*thread split/merge*
This is coming from: https://lore.kernel.org/linux-kselftest/CABVgOSnofuJQ_fiCL-8KdKezg3Hnqk3A+X5... But I'm attempting a thread jump... ;)
That's probably where we'll end up trying to hash out exactly what this format should be. Fortunately, I don't think any of these will require any per-test work, just changes to the KUnit implementation.
Yup, good.
- On the outer test report, there is no "plan" line (I was expecting "1..1"). Technically it's optional, but it seems like the information is available. :)
There's work underway to support this, but it's hit a few minor snags: https://lkml.org/lkml/2020/2/27/2155
Okay, cool. It's not critical, I don't think.
- The subtest should have its own "TAP version 14" line, and it should be using the diagnostic line prefix for the top-level test (this is what kselftest is doing).
Alas, TAP itself hasn't standardised subtests. Personally, I think it doesn't fundamentally matter which way we do this (I actually prefer the way we're doing it currently slightly), but converging with what kselftest does would be ideal.
I see the KTAP RFC doesn't discuss subtests at all, but kselftest actually already handles subtests. I strongly feel that line-start formatting is the correct way to deal with this, with each subtest having it's own self-contained KTAP. This allows for several important features:
the subtest, run on its own, needs no knowledge about its execution environment: it simply emits its standard KTAP output.
subtest output can be externally parsed separably, without any knowledge or parsing of the enclosing test.
I agree with both of these, but will save additional comments for the thread on my KTAP doc RFC.
For example, with my recent series[1], "make -C seccomp run_tests" produces:
TAP version 13 1..2 # selftests: seccomp: seccomp_bpf # TAP version 13 # 1..77 # # Starting 77 tests from 6 test cases. # # RUN global.mode_strict_support ... # # OK global.mode_strict_support # ok 1 global.mode_strict_support ... # ok 77 TSYNC.two_siblings_not_under_filter # # FAILED: 73 / 77 tests passed. # # Totals: pass:72 fail:4 xfail:1 xpass:0 skip:0 error:0 not ok 1 selftests: seccomp: seccomp_bpf # exit=1 # selftests: seccomp: seccomp_benchmark # not ok 2 selftests: seccomp: seccomp_benchmark # TIMEOUT
- There is no way to distinguish top-level TAP output from kernel log lines. I think we should stick with the existing marker, which is "# ", so that kernel output has no way to be interpreted as TAP details -- unless it intentionally starts adding "#"s. ;)
At the moment, we're doing this in KUnit tool by stripping anything before "TAP version 14" (e.g., the timestamp), and then only incuding lines which parse correctly (are a test plan, result, or a diagnostic line beginning with '#'). This has worked pretty well thus far, and we do have the ability to get results from debugfs instead of the kernel log, which won't have the same problems.
It's worth considering, though, particularly since our parser should handle this anyway without any changes.
For the KTAP parsing, actually think it's very important to include kernel log lines in the test output (as diagnostic lines), since they are "unexpected" (they fail to have the correct indentation) and may provide additional context for test failures when reading log files. (As in the "vmalloc: allocation failure" line in the quoted section above, to be included as a diagnostic line for test #3.)
- There is no summary line (to help humans). For example, the kselftest API produces a final pass/fail report.
Currently, we're relying on the kunit.py script to produce this, but it shouldn't be impossible to add to the kernel, particularly once the "KUnit Executor" changes mentioned above land.
Cool. Yeah, it's not required, but I think there are two use cases: humans running a single test (where is a summary is valuable, especially for long tests that scroll off the screen), and automation (where it can ignore the summary, as it will produce its own in a regularized fashion).
Taken together, I was expecting the output to be:
[ 36.611358] # TAP version 14 [ 36.611953] # 1..1 [ 36.611958] # # TAP version 14 [ 36.611954] # # 1..3 ... [ 36.622914] # # # overflow_calculation_test: s64: 21 arithmetic tests [ 36.624020] # # ok 1 - overflow_calculation_test ... [ 36.731096] # # # overflow_shift_test: ok: (s64)(0 << 63) == 0 [ 36.731840] # # ok 2 - overflow_shift_test ... [ 36.750294] kunit_try_catch: vmalloc: allocation failure: 18446744073709551615 bytes, mode:0xcc0(GFP_KERNEL),
nodemask=(null),cpuset=/,mems_allowed=0
... [ 36.805350] # # # overflow_allocation_test: devm_kzalloc detected saturation [ 36.807763] # # ok 3 - overflow_allocation_test [ 36.807763] # # # overflow: PASS [ 36.807765] # ok 1 - overflow [ 36.807767] # # kunit: PASS
But I assume there are threads on this that I've not read... :)
These discussions all seem to be coming to a head now, so this is probably just the kick we need to prioritise this a bit more. The KTAP thread hasn't covered all of these (particularly the subtest stuff) yet, so I confess I hadn't realised the extent of the divergence between KUnit and kselftest here.
Cool. Yeah, I'd like to keep things as close as possible. In looking at this again, I wonder if perhaps it would be better to change the "indent" from "# " to " ", which might make things more readable for both dmesg and terminal output:
[ 36.611358] TAP version 14 [ 36.611953] 1..1 [ 36.611958] TAP version 14 [ 36.611954] 1..3 ... [ 36.622914] # overflow_calculation_test: s64: 21 arithmetic tests [ 36.624020] ok 1 - overflow_calculation_test ... [ 36.731096] # overflow_shift_test: ok: (s64)(0 << 63) == 0 [ 36.731840] ok 2 - overflow_shift_test ... [ 36.750294] kunit_try_catch: vmalloc: allocation failure: 18446744073709551615 bytes, mode:0xcc0(GFP_KERNEL), nodemask=(null),cpuset=/,mems_allowed=0 ... [ 36.805350] # overflow_allocation_test: devm_kzalloc detected saturation [ 36.807763] ok 3 - overflow_allocation_test [ 36.807763] # overflow: PASS [ 36.807765] ok 1 - overflow [ 36.807767] # kunit: PASS
As it happens, subtests are a bit rare in kselftests right now, but for kunit, the "common" output (IIUC) will fundamentally be a top-level test running all the subtests, so we should get it right. :)
Personally, as a human I find the space prefix a bit easier to read. However, I think that in "normal" kernel log output it is unusual for a line to be prefixed with a hash (#), so this might be easier to both visually distinguish and for automated parsing. So I'm torn. I don't have a strong opinion on space vs. hash prefix for indicating sub-test. I think the KUnit convention of matching whatever was the prefix of the "TAP version 14" line is clever, but it would be nice to just pick a prefix and be done with it.
IMHO. -- Tim
-Kees
[1] https://git.kernel.org/pub/scm/linux/kernel/git/kees/linux.git/log/?h=selfte...
-- Kees Cook