Re: [PATCH v1 2/2] kunit: tool: parse KTAP compliant test output

[Daniel Latypov]

On Fri, Nov 4, 2022 at 12:48 PM Rae Moar <rmoar@xxxxxxxxxx> wrote:
>
> Change the KUnit parser to be able to parse test output that complies with
> the KTAP version 1 specification format found here:
> https://kernel.org/doc/html/latest/dev-tools/ktap.html. Ensure the parser
> is able to parse tests with the original KUnit test output format as
> well.
>
> KUnit parser now accepts any of the following test output formats:
>
> Original KUnit test output format:
>
>  TAP version 14
>  1..1
>    # Subtest: kunit-test-suite
>    1..3
>    ok 1 - kunit_test_1
>    ok 2 - kunit_test_2
>    ok 3 - kunit_test_3
>  # kunit-test-suite: pass:3 fail:0 skip:0 total:3
>  # Totals: pass:3 fail:0 skip:0 total:3
>  ok 1 - kunit-test-suite
>
> KTAP version 1 test output format:
>
>  KTAP version 1
>  1..1
>    KTAP version 1
>    1..3
>    ok 1 kunit_test_1
>    ok 2 kunit_test_2
>    ok 3 kunit_test_3
>  ok 1 kunit-test-suite
>
> New KUnit test output format (preferred for KUnit tests):
>
>  KTAP version 1
>  1..1
>    # Subtest: kunit-test-suite
>    KTAP version 1
>    1..3
>    ok 1 kunit_test_1
>    ok 2 kunit_test_2
>    ok 3 kunit_test_3
>  # kunit-test-suite: pass:3 fail:0 skip:0 total:3
>  # Totals: pass:3 fail:0 skip:0 total:3
>  ok 1 kunit-test-suite
>
> Signed-off-by: Rae Moar <rmoar@xxxxxxxxxx>

Reviewed-by: Daniel Latypov <dlatypov@xxxxxxxxxx>

Looks good to me.
Some comments below, but nothing we have to address in this patch, IMO.

> ---
> Note: this patch is based on the linux-kselftest/kunit branch.
> ---
> tools/testing/kunit/kunit_parser.py           | 69 ++++++++++++-------
>  tools/testing/kunit/kunit_tool_test.py        |  8 +++
>  .../test_data/test_parse_ktap_output.log      |  8 +++
>  3 files changed, 60 insertions(+), 25 deletions(-)
>  create mode 100644 tools/testing/kunit/test_data/test_parse_ktap_output.log
>
> diff --git a/tools/testing/kunit/kunit_parser.py b/tools/testing/kunit/kunit_parser.py
> index a56c75a973b5..abb69f898263 100644
> --- a/tools/testing/kunit/kunit_parser.py
> +++ b/tools/testing/kunit/kunit_parser.py
> @@ -441,6 +441,7 @@ def parse_diagnostic(lines: LineStream) -> List[str]:
>         - '# Subtest: [test name]'
>         - '[ok|not ok] [test number] [-] [test name] [optional skip
>                 directive]'
> +       - 'KTAP version [version number]'
>
>         Parameters:
>         lines - LineStream of KTAP output to parse
> @@ -449,8 +450,9 @@ def parse_diagnostic(lines: LineStream) -> List[str]:
>         Log of diagnostic lines
>         """
>         log = []  # type: List[str]
> -       while lines and not TEST_RESULT.match(lines.peek()) and not \
> -                       TEST_HEADER.match(lines.peek()):
> +       non_diagnostic_lines = [TEST_RESULT, TEST_HEADER, KTAP_START]
> +       while lines and not any(re.match(lines.peek())
> +                       for re in non_diagnostic_lines):
>                 log.append(lines.pop())
>         return log
>
> @@ -496,6 +498,12 @@ def print_test_header(test: Test) -> None:
>         test - Test object representing current test being printed
>         """
>         message = test.name
> +       if message == "":
> +               # KUnit tests print a Subtest header line that provides the name
> +               # of the test suite. But the subtest header line isn't required
> +               # by the KTAP spec, so use a placeholder name "Test suite" in that
> +               # case.
> +               message = "Test suite"


(something we can address in a later change)

Hmm, consider the following input

KTAP version 1
1..1
  KTAP version 1
  1..1
    KTAP version 1
    1..1
      ok 1 - subtest1
    ok 1 - test1
  ok 1 - suite

$ ./tools/testing/kunit/kunit.py parse < /tmp/example_nested_ktap
============================================================
================== Test suite (1 subtest) ==================
================== Test suite (1 subtest) ==================
[PASSED] subtest1
====================== [PASSED] test1 ======================
====================== [PASSED] suite ======================
============================================================

I wonder if the duplicate "Test suite" line would be confusing.
This also points to a slightly bigger problem that kunit_parser.py
doesn't have a good way to format 3+ layers of tests atm.

I don't know if there's another placeholder name we can give that
might be less confusing.

>         if test.expected_count:
>                 if test.expected_count == 1:
>                         message += ' (1 subtest)'
> @@ -647,13 +655,13 @@ def bubble_up_test_results(test: Test) -> None:
>         elif test.counts.get_status() == TestStatus.TEST_CRASHED:
>                 test.status = TestStatus.TEST_CRASHED
>
> -def parse_test(lines: LineStream, expected_num: int, log: List[str]) -> Test:
> +def parse_test(lines: LineStream, expected_num: int, log: List[str], is_subtest: bool) -> Test:
>         """
>         Finds next test to parse in LineStream, creates new Test object,
>         parses any subtests of the test, populates Test object with all
>         information (status, name) about the test and the Test objects for
>         any subtests, and then returns the Test object. The method accepts
> -       three formats of tests:
> +       four formats of tests:
>
>         Accepted test formats:
>
> @@ -674,6 +682,16 @@ def parse_test(lines: LineStream, expected_num: int, log: List[str]) -> Test:
>         [subtests]
>         ok 1 name
>
> +       - KTAP subtest header (in compliance with KTAP specification)
> +
> +       Example:
> +
> +    # May include subtest header line here
> +       KTAP version 1
> +       1..3
> +       [subtests]
> +       ok 1 name
> +
>         - Test result line
>
>         Example:
> @@ -685,6 +703,7 @@ def parse_test(lines: LineStream, expected_num: int, log: List[str]) -> Test:
>         expected_num - expected test number for test to be parsed
>         log - list of strings containing any preceding diagnostic lines
>                 corresponding to the current test
> +       is_subtest - boolean indicating whether test is a subtest
>
>         Return:
>         Test object populated with characteristics and any subtests
> @@ -692,21 +711,22 @@ def parse_test(lines: LineStream, expected_num: int, log: List[str]) -> Test:
>         test = Test()
>         test.log.extend(log)
>         parent_test = False
> -       main = parse_ktap_header(lines, test)
> -       if main:
> -               # If KTAP/TAP header is found, attempt to parse
> -               # test plan
> +       if not is_subtest:
> +               # If parsing the main test, attempt to parse KTAP/TAP header
> +               # and test plan
>                 test.name = "main"
> +               parse_ktap_header(lines, test)
>                 parse_test_plan(lines, test)
>                 parent_test = True
>         else:
> -               # If KTAP/TAP header is not found, test must be subtest
> -               # header or test result line so parse attempt to parser
> -               # subtest header
> -               parent_test = parse_test_header(lines, test)
> +               # If test is a subtest, attempt to parse test suite header
> +               # (either subtest line and/or KTAP/TAP version line)
> +               subtest_line = parse_test_header(lines, test)
> +               ktap_line = parse_ktap_header(lines, test)
> +               parent_test = subtest_line or ktap_line
>                 if parent_test:
> -                       # If subtest header is found, attempt to parse
> -                       # test plan and print header
> +                       # If subtest header and/or KTAP/version line is found, attempt
> +                       # to parse test plan and print header
>                         parse_test_plan(lines, test)
>                         print_test_header(test)
>         expected_count = test.expected_count
> @@ -721,7 +741,7 @@ def parse_test(lines: LineStream, expected_num: int, log: List[str]) -> Test:
>                 sub_log = parse_diagnostic(lines)
>                 sub_test = Test()
>                 if not lines or (peek_test_name_match(lines, test) and
> -                               not main):
> +                               is_subtest):
>                         if expected_count and test_num <= expected_count:
>                                 # If parser reaches end of test before
>                                 # parsing expected number of subtests, print
> @@ -735,20 +755,19 @@ def parse_test(lines: LineStream, expected_num: int, log: List[str]) -> Test:
>                                 test.log.extend(sub_log)
>                                 break
>                 else:
> -                       sub_test = parse_test(lines, test_num, sub_log)
> +                       sub_test = parse_test(lines, test_num, sub_log, True)
>                 subtests.append(sub_test)
>                 test_num += 1
>         test.subtests = subtests
> -       if not main:
> +       if is_subtest:
>                 # If not main test, look for test result line
>                 test.log.extend(parse_diagnostic(lines))
> -               if (parent_test and peek_test_name_match(lines, test)) or \
> -                               not parent_test:
> -                       parse_test_result(lines, test, expected_num)
> -               else:
> +               if subtest_line and not peek_test_name_match(lines, test):
>                         test.add_error('missing subtest result line!')
> +               else:
> +                       parse_test_result(lines, test, expected_num)

This change isn't a straightforward change of the logic like
s/main/not is_subtest.
But looking at it, it seems fine.

One example input would be

 KTAP version 1
 1..2
   # Subtest: suite1
   KTAP version 1
   1..1
   ok 1 test1
 # ok 1 suite1
 ok 2 suite2

We get output like this

$ ./tools/testing/kunit/kunit.py parse < /tmp/out
[14:54:44] ============================================================
[14:54:44] ==================== suite1 (1 subtest) ====================
[14:54:44] [PASSED] test1
[14:54:44] [ERROR] Test: suite1: missing subtest result line!
[14:54:44] # Subtest: suite1
[14:54:44] KTAP version 1
[14:54:44] 1..1
[14:54:44] # ok 1 suite1
[14:54:44] ===================== [CRASHED] suite1 =====================
[14:54:44] [PASSED] suite2
[14:54:44] ============================================================

So it handles it about as well as we could expect.

Note: kunit.py is indeed saying the kernel crashed even though there's
"kernel output" after the missing line. But this is a pre-existing
condition. It already doesn't check to see that the output is
truncated before saying "CRASHED"