Re: RFC: KTAP documentation - expected messages

21 Jun 2020


      On 2020-06-21 17:45, Frank Rowand wrote:
...
Tim Bird started a thread [1] proposing that he document the selftest result
format used by Linux kernel tests.
[1] https://lore.kernel.org/r/CY4PR13MB1175B804E31E502221BC8163FD830@CY4PR13MB11...
The issue of messages generated by the kernel being tested (that are not
messages directly created by the tests, but are instead triggered as a
side effect of the test) came up.  In this thread, I will call these
messages "expected messages".  Instead of sidetracking that thread with
a proposal to handle expected messages, I am starting this new thread.
I implemented an API for expected messages that are triggered by tests
in the Devicetree unittest code, with the expectation that the specific
details may change when the Devicetree unittest code adapts the KUnit
API.  It seems appropriate to incorporate the concept of expected
messages in Tim's documentation instead of waiting to address the
subject when the Devicetree unittest code adapts the KUnit API, since
Tim's document may become the kernel selftest standard.
Instead of creating a very long email containing multiple objects,
I will reply to this email with a separate reply for each of:
The "expected messages" API implemention and use can be from
  drivers/of/unittest.c in the mainline kernel.
of_unittest_expect - A proof of concept perl program to filter console
                       output containing expected messages output
                   of_unittest_expect is also available by cloning
                   https://github.com/frowand/dt_tools.git


An example raw console output with timestamps and expect messages.
An example of console output processed by filter program
  of_unittest_expect to be more human readable.  The expected
  messages are not removed, but are flagged.
An example of console output processed by filter program
  of_unittest_expect to be more human readable.  The expected
  messages are removed instead of being flagged.
# reply 2/5
#!/usr/bin/perl
# SPDX-License-Identifier: GPL-2.0
#
# Copyright 2020 Sony Corporation
#
# Author: Frank Rowand
# This program is meant to be an aid to reading the output of the Linux
# kernel devicetree unittest (drivers/of/unitest.c).  A design goal of
# unittest is that the output is directly usable without a helper program
# such as this one.
$VUFX = "200115a";
use strict 'refs';
use strict subs;
use Getopt::Long;
use Text::Wrap;
# strip off everything before final "/"
(undef, $script_name) = split(/^.*//, $0);
#______________________________________________________________________________
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 {
    		print "ERROR: type not recognized: $type\n";
    		return 0;
    	}
}
# should not get here
    print "ERROR: $script_name internal error, at end of compare()\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-strip-ts      do not strip leading timestamp
    --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.
Various unittests may trigger kernel messages from outside the
  unittest code.  The unittest annotates any such message with
  an EXPECT begin before triggering the message, and an EXPECT
  end after triggering the message.
If an expected message does not occur, that will be reported.
If EXPECT begin and EXPECT end lines do not match, that will
  be reported.  If nested, EXPECT end lines must be in the reverse
  order of the corresponding EXPECT begin lines.
EXPECT begin and EXPECT end lines can contain special patterns:
<<int>> matches: [+-]*[0-9]+
     <<hex>> matches: (0x)*[0-9a-f]+
Default:
    - strip timestamps
EXPECT begin and EXPECT end lines are suppressed.
  Lines that match an EXPECT line are flagged with a leading 'ok'.
  Lines reporting a $script_name warning or error are flagged
     with a leading '**'.
  Lines reporting start or end of the unittests are flagged
     with a leading '->'.
  Lines reporting a unittest test FAIL are flagged
     with a leading '>>'.
";
return {};
}
#______________________________________________________________________________
#______________________________________________________________________________
# save for usage()
if (!GetOptions(
    "h"               => $help,
    "help"            => $help,
    "hide-expect"     => $hide_expect,
    "line-num"        => $print_line_num,
    "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 1;
}
if ($no_strip_ts) {
    $strip_ts = 1;
    $no_strip_ts = 0;
} else {
    $strip_ts = 0;
    $no_strip_ts = 1;
}
# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
if ($help){
&usage;
exit 1;
}
# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
if ($version) {
    print STDERR "\n$script_name  $VUFX\n\n";
    print STDERR "\n";
exit 0;
}
#______________________________________________________________________________
# $debug = 1;
# zzz:
#if ($#ARGV != 1) {
#	print STDERR "\n";
#	print STDERR "Required arguments: two file names\n";
#	print STDERR "\n";
#
#	exit 0;
#}
# $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 = "### 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) {
print "** ERROR: EXPECT end without any EXPECT begin:\n";
    		print "       end ---> $line\n";
} elsif (! $found) {
    		if ($print_line_num) {
    			$line_num = sprintf("%4s ", $.);
    		}
printf "** %s%s$script_name WARNING - not found ---> %s\n", $line_num,  $timestamp, $data;
} elsif (! compare($data, $begin)) {
    		print "** ERROR: EXPECT end does not match EXPECT begin:\n";
    		print "       begin -> $begin\n";
    		print "       end ---> $line\n";
    	}
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 /) {
    	$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 (@begin) {
    print "** ERROR: EXPECT begin without any EXPECT end:\n";
    print "          This list may be misleading.\n";
    foreach $begin (@begin) {
    	print "       begin ---> $begin\n";
    }
}
#______________________________________________________________________________
# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
#_______________________________________________________________________________
# vi config follows:
# ~/.exrc must contain "set modelines" for tabs to be set automatically
# ex:set tabstop=3 shiftwidth=3 sts=0:

2024

2023

2022

2021

2020

2019

2018

2017

Re: RFC: KTAP documentation - expected messages