Re: [PATCH] kunit: tool: make parser preserve whitespace when printing test log

[David Gow]

On Thu, Dec 1, 2022 at 2:54 AM 'Daniel Latypov' via KUnit Development
<kunit-dev@xxxxxxxxxxxxxxxx> wrote:
>
> Currently, kunit_parser.py is stripping all leading whitespace to make
> parsing easier. But this means we can't accurately show kernel output
> for failing tests or when the kernel crashes.
>
> Embarassingly, this affects even KUnit's own output, e.g.
> [13:40:46] Expected 2 + 1 == 2, but
> [13:40:46] 2 + 1 == 3 (0x3)
> [13:40:46] not ok 1 example_simple_test
> [13:40:46] [FAILED] example_simple_test
>
> After this change, here's what the output in context would look like
> [13:40:46] =================== example (4 subtests) ===================
> [13:40:46] # example_simple_test: initializing
> [13:40:46] # example_simple_test: EXPECTATION FAILED at lib/kunit/kunit-example-test.c:29
> [13:40:46] Expected 2 + 1 == 2, but
> [13:40:46]     2 + 1 == 3 (0x3)
> [13:40:46] [FAILED] example_simple_test
> [13:40:46] [SKIPPED] example_skip_test
> [13:40:46] [SKIPPED] example_mark_skipped_test
> [13:40:46] [PASSED] example_all_expect_macros_test
> [13:40:46]     # example: initializing suite
> [13:40:46] # example: pass:1 fail:1 skip:2 total:4
> [13:40:46] # Totals: pass:1 fail:1 skip:2 total:4
> [13:40:46] ===================== [FAILED] example =====================
>
> This example shows one minor cosmetic defect this approach has.
> The test counts lines prevent us from dedenting the suite-level output.
> But at the same time, any form of non-KUnit output would do the same
> unless it happened to be indented as well.
>
> Signed-off-by: Daniel Latypov <dlatypov@xxxxxxxxxx>
> ---

I agree that this is a good idea.

Personally, I think we could avoid some of the 'dedent' issues by
disabling the test statistics lines when run via kunit.py (if
raw_output is not enabled). That's probably better as a separate
patch, though, so this looks good to go.

Reviewed-by: David Gow <davidgow@xxxxxxxxxx>

Cheers,
-- David

>  tools/testing/kunit/kunit.py           |  2 +-
>  tools/testing/kunit/kunit_parser.py    | 27 +++++++++++++-------------
>  tools/testing/kunit/kunit_tool_test.py |  2 ++
>  3 files changed, 16 insertions(+), 15 deletions(-)
>
> diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
> index e7b6549712d6..43fbe96318fe 100755
> --- a/tools/testing/kunit/kunit.py
> +++ b/tools/testing/kunit/kunit.py
> @@ -202,7 +202,7 @@ def parse_tests(request: KunitParseRequest, metadata: kunit_json.Metadata, input
>                 if request.raw_output == 'all':
>                         pass
>                 elif request.raw_output == 'kunit':
> -                       output = kunit_parser.extract_tap_lines(output, lstrip=False)
> +                       output = kunit_parser.extract_tap_lines(output)
>                 for line in output:
>                         print(line.rstrip())
>                 parse_time = time.time() - parse_start
> diff --git a/tools/testing/kunit/kunit_parser.py b/tools/testing/kunit/kunit_parser.py
> index 99b8f058db40..a225799f6b1b 100644
> --- a/tools/testing/kunit/kunit_parser.py
> +++ b/tools/testing/kunit/kunit_parser.py
> @@ -13,6 +13,7 @@ from __future__ import annotations
>  from dataclasses import dataclass
>  import re
>  import sys
> +import textwrap
>
>  from enum import Enum, auto
>  from typing import Iterable, Iterator, List, Optional, Tuple
> @@ -208,12 +209,12 @@ class LineStream:
>
>  # Parsing helper methods:
>
> -KTAP_START = re.compile(r'KTAP version ([0-9]+)$')
> -TAP_START = re.compile(r'TAP version ([0-9]+)$')
> -KTAP_END = re.compile('(List of all partitions:|'
> +KTAP_START = re.compile(r'\s*KTAP version ([0-9]+)$')
> +TAP_START = re.compile(r'\s*TAP version ([0-9]+)$')
> +KTAP_END = re.compile(r'\s*(List of all partitions:|'
>         'Kernel panic - not syncing: VFS:|reboot: System halted)')
>
> -def extract_tap_lines(kernel_output: Iterable[str], lstrip=True) -> LineStream:
> +def extract_tap_lines(kernel_output: Iterable[str]) -> LineStream:
>         """Extracts KTAP lines from the kernel output."""
>         def isolate_ktap_output(kernel_output: Iterable[str]) \
>                         -> Iterator[Tuple[int, str]]:
> @@ -239,11 +240,8 @@ def extract_tap_lines(kernel_output: Iterable[str], lstrip=True) -> LineStream:
>                                 # stop extracting KTAP lines
>                                 break
>                         elif started:
> -                               # remove the prefix and optionally any leading
> -                               # whitespace. Our parsing logic relies on this.
> +                               # remove the prefix, if any.
>                                 line = line[prefix_len:]
> -                               if lstrip:
> -                                       line = line.lstrip()
>                                 yield line_num, line
>         return LineStream(lines=isolate_ktap_output(kernel_output))
>
> @@ -298,7 +296,7 @@ def parse_ktap_header(lines: LineStream, test: Test) -> bool:
>         lines.pop()
>         return True
>
> -TEST_HEADER = re.compile(r'^# Subtest: (.*)$')
> +TEST_HEADER = re.compile(r'^\s*# Subtest: (.*)$')
>
>  def parse_test_header(lines: LineStream, test: Test) -> bool:
>         """
> @@ -322,7 +320,7 @@ def parse_test_header(lines: LineStream, test: Test) -> bool:
>         lines.pop()
>         return True
>
> -TEST_PLAN = re.compile(r'1\.\.([0-9]+)')
> +TEST_PLAN = re.compile(r'^\s*1\.\.([0-9]+)')
>
>  def parse_test_plan(lines: LineStream, test: Test) -> bool:
>         """
> @@ -350,9 +348,9 @@ def parse_test_plan(lines: LineStream, test: Test) -> bool:
>         lines.pop()
>         return True
>
> -TEST_RESULT = re.compile(r'^(ok|not ok) ([0-9]+) (- )?([^#]*)( # .*)?$')
> +TEST_RESULT = re.compile(r'^\s*(ok|not ok) ([0-9]+) (- )?([^#]*)( # .*)?$')
>
> -TEST_RESULT_SKIP = re.compile(r'^(ok|not ok) ([0-9]+) (- )?(.*) # SKIP(.*)$')
> +TEST_RESULT_SKIP = re.compile(r'^\s*(ok|not ok) ([0-9]+) (- )?(.*) # SKIP(.*)$')
>
>  def peek_test_name_match(lines: LineStream, test: Test) -> bool:
>         """
> @@ -511,8 +509,9 @@ def print_test_header(test: Test) -> None:
>
>  def print_log(log: Iterable[str]) -> None:
>         """Prints all strings in saved log for test in yellow."""
> -       for m in log:
> -               stdout.print_with_timestamp(stdout.yellow(m))
> +       formatted = textwrap.dedent('\n'.join(log))
> +       for line in formatted.splitlines():
> +               stdout.print_with_timestamp(stdout.yellow(line))
>
>  def format_test_result(test: Test) -> str:
>         """
> diff --git a/tools/testing/kunit/kunit_tool_test.py b/tools/testing/kunit/kunit_tool_test.py
> index 1ef921ac4331..0c2190514103 100755
> --- a/tools/testing/kunit/kunit_tool_test.py
> +++ b/tools/testing/kunit/kunit_tool_test.py
> @@ -336,12 +336,14 @@ class KUnitParserTest(unittest.TestCase):
>                 KTAP version 1
>                 1..1
>                   Test output.
> +                   Indented more.
>                 not ok 1 test1
>                 """
>                 result = kunit_parser.parse_run_tests(output.splitlines())
>                 self.assertEqual(kunit_parser.TestStatus.FAILURE, result.status)
>
>                 self.print_mock.assert_any_call(StrContains('Test output.'))
> +               self.print_mock.assert_any_call(StrContains('  Indented more.'))
>                 self.noPrintCallContains('not ok 1 test1')
>
>  def line_stream_from_strs(strs: Iterable[str]) -> kunit_parser.LineStream:
>
> base-commit: 0f08f3e2a0186dfb8e33cb46105228eb18448a0e
> --
> 2.38.1.584.g0f3c55d4c2-goog
>
> --
> You received this message because you are subscribed to the Google Groups "KUnit Development" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to kunit-dev+unsubscribe@xxxxxxxxxxxxxxxx.
> To view this discussion on the web visit https://groups.google.com/d/msgid/kunit-dev/20221130185419.2552673-1-dlatypov%40google.com.

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature