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@google.com --- 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
On Thu, Dec 1, 2022 at 2:54 AM 'Daniel Latypov' via KUnit Development kunit-dev@googlegroups.com 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@google.com
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@google.com
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_startdiff --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@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/kunit-dev/20221130185419.2552673-1-dlatypo....
On Tue, Dec 6, 2022 at 7:43 PM David Gow davidgow@google.com wrote:
On Thu, Dec 1, 2022 at 2:54 AM 'Daniel Latypov' via KUnit Development
<snip>
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@google.com
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.
I was of a similar mindset initially, which is why I held off on sending this patch out. But as noted at the end of the commit desc, literally ~any kernel output will cause this to happen. And the whole point of this patch is to show such output, newly unmangled ;)
Secondly, only the kunit_{info,warn,err} logs are indented like this. I think most test output would be coming from code outside the test file, i.e. normal pr_info() calls.
But I figured I should still call it out somewhere in this email though, since it does look a bit strange. Maybe it didn't need to be as prominently as the commit desc.
Also, I was leaning towards just hiding it via some filtering in kunit_parser.py, but Rae's reply [1] made me more unsure about which way to go. So I'm thinking of leaving the lines in there for now. [1] https://lore.kernel.org/linux-kselftest/CA+GJov6QKNy5fxkiu0P29WDtFgNs0GP4T27...
Daniel
linux-kselftest-mirror@lists.linaro.org
-
Daniel Latypov -
David Gow