of: unittest: add program to process EXPECT messages
authorFrank Rowand <frank.rowand@sony.com>
Tue, 1 Feb 2022 18:14:13 +0000 (12:14 -0600)
committerRob Herring <robh@kernel.org>
Mon, 28 Feb 2022 21:20:32 +0000 (15:20 -0600)
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 <frank.rowand@sony.com>
Signed-off-by: Rob Herring <robh@kernel.org>
Link: https://lore.kernel.org/r/20220201181413.2719955-1-frowand.list@gmail.com
Documentation/devicetree/of_unittest.rst
scripts/dtc/of_unittest_expect [new file with mode: 0755]

index 2afe41a..8864b52 100644 (file)
@@ -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 (executable)
index 0000000..96b12d9
--- /dev/null
@@ -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(/<</, $expect);
+               ($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':
+
+     <<int>> matches: [+-]*[0-9]+
+     <<hex>> 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 = <ARGV>) {' 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 = <ARGV>) {
+
+       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";
+       }
+}