From 8e4296c286ed7a3b69e619d5069493bdcc9a2b25 Mon Sep 17 00:00:00 2001 From: Frank Rowand Date: Tue, 1 Feb 2022 12:14:13 -0600 Subject: [PATCH] of: unittest: add program to process EXPECT messages If unittest detects a problem it will print a warning or error message to the console. Unittest also triggers warning and error messages from other kernel code as a result of intentionally bad unittest data. This has led to confusion as to whether the triggered messages are an expected result of a test or whether there is a real problem that is independent of unittest. EXPECT messages were added to unittest to report each triggered message that is expected, resulting in verbose console output. scripts/dtc/of_unittest is a new program that processes the EXPECT messages to determine whether the triggered messages occurred and also removes the excess verbosity of the EXPECT messages. More information is available from 'scripts/dtc/of_unittest_expect --help'. Signed-off-by: Frank Rowand Signed-off-by: Rob Herring Link: https://lore.kernel.org/r/20220201181413.2719955-1-frowand.list@gmail.com --- Documentation/devicetree/of_unittest.rst | 27 +- scripts/dtc/of_unittest_expect | 408 +++++++++++++++++++++++++++++++ 2 files changed, 432 insertions(+), 3 deletions(-) create mode 100755 scripts/dtc/of_unittest_expect diff --git a/Documentation/devicetree/of_unittest.rst b/Documentation/devicetree/of_unittest.rst index 2afe41a37148..8864b52d1195 100644 --- a/Documentation/devicetree/of_unittest.rst +++ b/Documentation/devicetree/of_unittest.rst @@ -24,7 +24,28 @@ from the unflattened device tree data structure. This interface is used by most of the device drivers in various use cases. -2. Test-data +2. Verbose Output (EXPECT) +========================== + +If unittest detects a problem it will print a warning or error message to +the console. Unittest also triggers warning and error messages from other +kernel code as a result of intentionally bad unittest data. This has led +to confusion as to whether the triggered messages are an expected result +of a test or whether there is a real problem that is independent of unittest. + +'EXPECT \ : text' (begin) and 'EXPECT / : text' (end) messages have been +added to unittest to report that a warning or error is expected. The +begin is printed before triggering the warning or error, and the end is +printed after triggering the warning or error. + +The EXPECT messages result in very noisy console messages that are difficult +to read. The script scripts/dtc/of_unittest_expect was created to filter +this verbosity and highlight mismatches between triggered warnings and +errors vs expected warnings and errors. More information is available +from 'scripts/dtc/of_unittest_expect --help'. + + +3. Test-data ============ The Device Tree Source file (drivers/of/unittest-data/testcases.dts) contains @@ -56,7 +77,7 @@ The assembly file is compiled into an object file (testcases.dtb.o), and is linked into the kernel image. -2.1. Adding the test data +3.1. Adding the test data ------------------------- Un-flattened device tree structure: @@ -191,7 +212,7 @@ properties are updated to the live tree's node by calling the function update_node_properties(). -2.2. Removing the test data +3.2. Removing the test data --------------------------- Once the test case execution is complete, selftest_data_remove is called in diff --git a/scripts/dtc/of_unittest_expect b/scripts/dtc/of_unittest_expect new file mode 100755 index 000000000000..96b12d9ea606 --- /dev/null +++ b/scripts/dtc/of_unittest_expect @@ -0,0 +1,408 @@ +#!/usr/bin/perl +# SPDX-License-Identifier: GPL-2.0 +# +# Copyright 2020, 2022 Sony Corporation +# +# Author: Frank Rowand + +# This program is meant to be an aid to reading the verbose output of +# on the console log that results from executing the Linux kernel +# devicetree unittest (drivers/of/unitest.c). + +$VUFX = "220201a"; + +use strict 'refs'; +use strict subs; + +use Getopt::Long; +use Text::Wrap; + +# strip off everything before final "/" +(undef, $script_name) = split(/^.*\//, $0); + +# following /usr/include/sysexits.h +$EX_OK=0; +$EX_USAGE=64; + + +#______________________________________________________________________________ +sub compare { + my ($expect, $got) = @_; + my $expect_next; + my $expect_next_lit; + my $got_next; + my $type; + + while ($expect) { + + ($expect_next, $type) = split(/<>/, $type); + $expect =~ s/^.*?>>//; # '?' is non-greedy, minimal match + + # literal, ignore all metacharacters when used in a regex + $expect_next_lit = quotemeta($expect_next); + + $got_next = $got; + $got_next =~ s/^($expect_next_lit).*/\1/; + $got =~ s/^$expect_next_lit//; + + if ($expect_next ne $got_next) { + return 0; + } + + if ($type eq "int") { + if ($got =~ /^[+-]*[0-9]+/) { + $got =~ s/^[+-]*[0-9]+//; + } else { + return 0; + } + } elsif ($type eq "hex") { + if ($got =~ /^(0x)*[0-9a-f]+/) { + $got =~ s/^(0x)*[0-9a-f]+//; + } else { + return 0; + } + } elsif ($type eq "") { + if ($expect_next ne $got_next) { + return 0; + } else { + return 1; + } + } else { + $internal_err++; + print "** ERROR: special pattern not recognized: <<$type>>, CONSOLE_LOG line: $.\n"; + return 0; + } + + } + + # should not get here + $internal_err++; + print "** ERROR: $script_name internal error, at end of compare(), CONSOLE_LOG line: $.\n"; + + return 0; +} + + +#______________________________________________________________________________ +sub usage { + +# ***** when editing, be careful to not put tabs in the string printed: + + print STDERR +" +usage: + + $script_name CONSOLE_LOG + + -h print program usage + --help print program usage + --hide-expect suppress output of EXPECTed lines + --line-num report line number of CONSOLE_LOG + --no-expect-stats do not report EXPECT statistics + --no-strip-ts do not strip leading console timestamps + --verbose do not suppress EXPECT begin and end lines + --version print program version and exit + + + Process a console log for EXPECTed test related messages to either + highlight expected devicetree unittest related messages or suppress + the messages. Leading console timestamps will be stripped. + + Various unittests may trigger kernel messages from outside the + unittest code. The unittest annotates that it expects the message + to occur with an 'EXPECT \\ : text' (begin) before triggering the + message, and an 'EXPECT / : text' (end) after triggering the message. + + If an expected message does not occur, that will be reported. + + For each expected message, the 'EXPECT \\ : text' (begin) and + 'EXPECT / : text' (end), 'text' will contain the message text. + + If 'EXPECT \\' (begin) and 'EXPECT /' (end) lines do not contain + matching 'text', that will be reported. + + If EXPECT lines are nested, 'EXPECT /' (end) lines must be in the + reverse order of the corresponding 'EXPECT \\' (begin) lines. + + 'EXPECT \\ : text' (begin) and 'EXPECT / : text' (end) lines can + contain special patterns in 'text': + + <> matches: [+-]*[0-9]+ + <> matches: (0x)*[0-9a-f]+ + + 'EXPECT \\' (begin) and 'EXPECT /' (end) lines are suppressed. + + A prefix is added to every line of output: + + 'ok ' Line matches an enclosing EXPECT begin/end pair + + '** ' Line reports $script_name warning or error + + '-> ' Line reports start or end of the unittests + + '>> ' Line reports a unittest test FAIL + + ' ' Lines that are not otherwise prefixed + + Issues detected in CONSOLE_LOG are reported to STDOUT, not to STDERR. + + Known Issues: + + --line-num causes the CONSOLE_LOG line number to be printed in 4 columns. + If CONSOLE_LOG contains more than 9999 lines then more columns will be + used to report the line number for lines greater than 9999 (eg for + lines 10000 - 99999, 5 columns will be used). +"; + + return {}; +} + +#______________________________________________________________________________ +#______________________________________________________________________________ + +if (!GetOptions( + "h" => \$help, + "help" => \$help, + "hide-expect" => \$hide_expect, + "line-num" => \$print_line_num, + "no-expect-stats" => \$no_expect_stats, + "no-strip-ts" => \$no_strip_ts, + "verbose" => \$verbose, + "version" => \$version, + )) { + print STDERR "\n"; + print STDERR "ERROR processing command line options\n"; + print STDERR "\n"; + print STDERR "For help, type '$script_name --help'\n"; + print STDERR "\n"; + + exit $EX_OK; +} + + +if ($no_strip_ts) { + $strip_ts = 1; + $no_strip_ts = 0; +} else { + $strip_ts = 0; + $no_strip_ts = 1; +} + + +# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +if ($help){ + + &usage; + + exit $EX_OK; +} + + +# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - + +if ($version) { + print STDERR "\n$script_name $VUFX\n\n"; + print STDERR "\n"; + + exit $EX_OK; +} + + +# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +if ($#ARGV != 0) { + + # Limit input files to exactly one. + # + # 'while ($line = ) {' in the code below supports multiple file + # names on the command line, but the EXPECT statistics are reported + # once for all input - it is not an expected use case to generate one + # set of statistics for multiple input files. + + print STDERR "\n"; + print STDERR "Required arguments: CONSOLE_LOG\n"; + print STDERR "\n"; + + exit $EX_USAGE; +} + + +#______________________________________________________________________________ + +# Patterns to match 'EXPECT \ : ' (begin) and 'EXPECT / : ' (end) +# +# $exp_* are used as regex match patterns, +# so '\\\\' in $exp_begin matches a single '\' +# quotemeta() does not do the right thing in this case +# +# $pr_fmt is the prefix that unittest prints for every message + +$pr_fmt = "### dt-test ### "; +$exp_begin = "${pr_fmt}EXPECT \\\\ : "; +$exp_end = "${pr_fmt}EXPECT / : "; + + +$line_num = ""; +$timestamp = ""; + +LINE: +while ($line = ) { + + chomp $line; + + $prefix = " "; ## 2 characters + + + if ($strip_ts) { + + $timestamp = $line; + + if ($timestamp =~ /^\[\s*[0-9]+\.[0-9]*\] /) { + ($timestamp, $null) = split(/]/, $line); + $timestamp = $timestamp . "] "; + + } else { + $timestamp = ""; + } + } + + $line =~ s/^\[\s*[0-9]+\.[0-9]*\] //; + + + # ----- find EXPECT begin + + if ($line =~ /^\s*$exp_begin/) { + $data = $line; + $data =~ s/^\s*$exp_begin//; + push @begin, $data; + + if ($verbose) { + if ($print_line_num) { + $line_num = sprintf("%4s ", $.); + } + printf "%s %s%s%s\n", $prefix, $line_num, $timestamp, $line; + } + + next LINE; + } + + + # ----- find EXPECT end + + if ($line =~ /^\s*$exp_end/) { + $data = $line; + $data =~ s/^\s*$exp_end//; + + if ($verbose) { + if ($print_line_num) { + $line_num = sprintf("%4s ", $.); + } + printf "%s %s%s%s\n", $prefix, $line_num, $timestamp, $line; + } + + $found = 0; + $no_begin = 0; + if (@found_or_begin > 0) { + $begin = pop @found_or_begin; + if (compare($data, $begin)) { + $found = 1; + } + } elsif (@begin > 0) { + $begin = pop @begin; + } else { + $no_begin = 1; + } + + if ($no_begin) { + + $expect_missing_begin++; + print "** ERROR: EXPECT end without any EXPECT begin:\n"; + print " end ---> $line\n"; + + } elsif (! $found) { + + if ($print_line_num) { + $line_num = sprintf("%4s ", $.); + } + + $expect_not_found++; + printf "** %s%s$script_name WARNING - not found ---> %s\n", + $line_num, $timestamp, $data; + + } elsif (! compare($data, $begin)) { + + $expect_missing_end++; + print "** ERROR: EXPECT end does not match EXPECT begin:\n"; + print " begin -> $begin\n"; + print " end ---> $line\n"; + + } else { + + $expect_found++; + + } + + next LINE; + } + + + # ----- not an EXPECT line + + if (($line =~ /^${pr_fmt}start of unittest - you will see error messages$/) || + ($line =~ /^${pr_fmt}end of unittest - [0-9]+ passed, [0-9]+ failed$/ ) ) { + $prefix = "->"; # 2 characters + } elsif ($line =~ /^${pr_fmt}FAIL /) { + $unittest_fail++; + $prefix = ">>"; # 2 characters + } + + $found = 0; + foreach $begin (@begin) { + if (compare($begin, $line)) { + $found = 1; + last; + } + } + + if ($found) { + $begin = shift @begin; + while (! compare($begin, $line)) { + push @found_or_begin, $begin; + $begin = shift @begin; + } + push @found_or_begin, $line; + + if ($hide_expect) { + $suppress_line = 1; + next LINE; + } + $prefix = "ok"; # 2 characters + } + + + if ($print_line_num) { + $line_num = sprintf("%4s ", $.); + } + + printf "%s %s%s%s\n", $prefix, $line_num, $timestamp, $line; +} + +if (! $no_expect_stats) { + print "\n"; + print "** EXPECT statistics:\n"; + print "**\n"; + printf "** EXPECT found : %4i\n", $expect_found; + printf "** EXPECT not found : %4i\n", $expect_not_found; + printf "** missing EXPECT begin : %4i\n", $expect_missing_begin; + printf "** missing EXPECT end : %4i\n", $expect_missing_end; + printf "** unittest FAIL : %4i\n", $unittest_fail; + printf "** internal error : %4i\n", $internal_err; +} + +if (@begin) { + print "** ERROR: EXPECT begin without any EXPECT end:\n"; + print " This list may be misleading.\n"; + foreach $begin (@begin) { + print " begin ---> $begin\n"; + } +} -- 2.11.0