Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Subject: Re: RFC: KTAP documentation - expected messages
From:   Frank Rowand <frowand.list@gmail.com>
To:     "Bird, Tim" <Tim.Bird@sony.com>,
        "shuah@kernel.org" <shuah@kernel.org>,
        "linux-kselftest@vger.kernel.org" <linux-kselftest@vger.kernel.org>,
        Brendan Higgins <brendanhiggins@google.com>,
        David Gow <davidgow@google.com>,
        Kees Cook <keescook@chromium.org>,
        Paolo Bonzini <pbonzini@redhat.com>
Cc:     "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>
References: <d38bf9f9-8a39-87a6-8ce7-d37e4a641675@gmail.com>
Message-ID: <19d771b3-54e5-11fb-86d9-2b56ab8190eb@gmail.com>
Date:   Sun, 21 Jun 2020 17:50:04 -0500
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.8.0
MIME-Version: 1.0
In-Reply-To: <d38bf9f9-8a39-87a6-8ce7-d37e4a641675@gmail.com>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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@CY4PR13MB1175.namprd13.prod.outlook.com
> 
> 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: