2022-02-02 07:49:19

by Frank Rowand

[permalink] [raw]
Subject: [PATCH 1/1] of: unittest: add program to process EXPECT messages

From: Frank Rowand <[email protected]>

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 <[email protected]>
---
permissions for scripts/dtc/of_unittest should be 770

I will reply to this message with the usage message from
'scripts/dtc/of_unittest_expect --help'.

I will also reply with examples of raw and processed console logs.

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(/<</, $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";
+ }
+}
--
Frank Rowand <[email protected]>


2022-02-02 13:41:42

by Frank Rowand

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

On 2/1/22 12:14 PM, [email protected] wrote:
> From: Frank Rowand <[email protected]>
>

< snip >

> I will also reply with examples of raw and processed console logs.

< snip >

In 5.6-rc1 there was a problem with the test of gpio hogs. This is
the raw console log that showed the problem, filtered by of_unittest_expect.

Note the line prefixed with '** ' that report that expected
error messages were not found.

Note the line prefixed with '>> ' which contains the unittest
FAIL message.

Note the summary at the end of the output:

** EXPECT statistics:
**
** EXPECT found : 45
** EXPECT not found : 1
** missing EXPECT begin : 0
** missing EXPECT end : 0
** unittest FAIL : 1
** internal error : 0


$ scripts/dtc/of_unittest_expect ../linux--5.6-rc/console_gpio_unittest
Android Bootloader - UART_DM Initialized!!!
[0] welcome to lk

[10] platform_init()
[10] target_init()
[10] Display Init: Start
[10] display_init(),target_id=10.
[30] Config MIPI_VIDEO_PANEL.
[30] Turn on MIPI_VIDEO_PANEL.
[50] Video lane tested successfully
[50] Display Init: Done
[80] Loading keystore failed status 5 [80] ERROR: scm_protect_keystore Failed[200] USB init ept @ 0xf96b000
[220] fastboot_init()
[220] udc_start()
[350] -- reset --
[350] -- portchange --
[460] -- reset --
[460] -- portchange --
[650] fastboot: processing commands
[760] fastboot: download:00f3f800
[1250] fastboot: boot
[1260] Found Appeneded Flattened Device tree
[1270] cmdline: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
[1290] Updating device tree: start
[1290] Updating device tree: done
[1300] booting linux @ 0x8000, ramdisk @ 0x2000000 (9533134), tags/device tree @ 0x1e00000
[1300] Turn off MIPI_VIDEO_PANEL.
[1300] Continuous splash enabled, keeping panel alive.
Booting Linux on physical CPU 0x0
Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020
CPU: ARMv7 Processor [512f06f0] revision 0 (ARMv7), cr=10c5787d
CPU: div instructions available: patching division code
CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
OF: fdt: Machine model: Qualcomm APQ8074 Dragonboard
Memory policy: Data cache writealloc
cma: Reserved 256 MiB at 0x70000000
percpu: Embedded 19 pages/cpu s48256 r8192 d21376 u77824
Built 1 zonelists, mobility grouping on. Total pages: 490240
Kernel command line: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
mem auto-init: stack:off, heap alloc:off, heap free:off
Memory: 1662424K/1967104K available (9216K kernel code, 946K rwdata, 3852K rodata, 1024K init, 269K bss, 42536K reserved, 262144K cma-reserved, 1048576K highmem)
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
rcu: Preemptible hierarchical RCU implementation.
rcu: RCU event tracing is enabled.
Tasks RCU enabled.
rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
random: get_random_bytes called from start_kernel+0x52c/0x76c with crng_init=0
arch_timer: cp15 and mmio timer(s) running at 19.20MHz (virt/virt).
clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
Switching to timer-based delay loop, resolution 52ns
Console: colour dummy device 80x30
Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
qcom_scm: convention: smc legacy
Setting up static identity map for 0x300000 - 0x300060
rcu: Hierarchical SRCU implementation.
smp: Bringing up secondary CPUs ...
CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
smp: Brought up 1 node, 2 CPUs
SMP: Total of 2 processors activated (76.80 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
VFP support v0.3: implementor 51 architecture 64 part 6f variant 2 rev 0
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
pinctrl core: initialized pinctrl subsystem
thermal_sys: Registered thermal governor 'step_wise'
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
cpuidle: using governor menu
hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 8 bytes.
iommu: Default domain type: Translated
vgaarb: loaded
SCSI subsystem initialized
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
qcom_scm: convention: smc legacy
Advanced Linux Sound Architecture Driver Initialized.
clocksource: Switched to clocksource arch_sys_counter
NET: Registered protocol family 2
tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
TCP: Hash tables configured (established 8192 bind 8192)
UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
PCI: CLS 0 bytes, default 64
Trying to unpack rootfs image as initramfs...
Freeing initrd memory: 9312K
hw perfevents: enabled with armv7_krait PMU driver, 5 counters available
Initialise system trusted keyrings
workingset: timestamp_bits=30 max_order=19 bucket_order=0
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
Key type cifs.idmap registered
jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
fuse: init (API version 7.31)
Key type asymmetric registered
Asymmetric key parser 'x509' registered
bounce: pool size: 64 pages
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
io scheduler mq-deadline registered
io scheduler kyber registered
bam-dma-engine f9944000.dma-controller: WARN: Device release is not defined so it is not safe to unbind this driver while in use
msm_serial f991e000.serial: msm_serial: detected port #0
msm_serial f991e000.serial: uartclk = 7372800
f991e000.serial: ttyMSM0 at MMIO 0xf991e000 (irq = 28, base_baud = 460800) is a MSM
msm_serial: console setup on port #0
printk: console [ttyMSM0] enabled
msm_serial: driver initialized
brd: module loaded
loop: module loaded
SCSI Media Changer driver v0.25
spmi spmi-0: PMIC arbiter version v1 (0x20000002)
s1: supplied by regulator-dummy
s2: supplied by regulator-dummy
s3: supplied by regulator-dummy
s4: Bringing 5100000uV into 5000000-5000000uV
l1: supplied by regulator-dummy
l2: supplied by regulator-dummy
l3: supplied by regulator-dummy
l4: supplied by regulator-dummy
l5: supplied by regulator-dummy
l6: supplied by regulator-dummy
l7: supplied by regulator-dummy
l8: supplied by regulator-dummy
l9: supplied by regulator-dummy
l10: supplied by regulator-dummy
l11: supplied by regulator-dummy
l12: supplied by regulator-dummy
l13: supplied by regulator-dummy
l14: supplied by regulator-dummy
l15: supplied by regulator-dummy
l16: supplied by regulator-dummy
l17: supplied by regulator-dummy
l18: supplied by regulator-dummy
l19: supplied by regulator-dummy
l20: supplied by regulator-dummy
l21: supplied by regulator-dummy
l22: supplied by regulator-dummy
l23: supplied by regulator-dummy
l24: supplied by regulator-dummy
lvs1: supplied by regulator-dummy
lvs2: supplied by regulator-dummy
lvs3: supplied by regulator-dummy
5vs1: supplied by s4
5vs2: supplied by s4
libphy: Fixed MDIO Bus: probed
SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256) (6 bit encapsulation enabled).
CSLIP: code copyright 1989 Regents of the University of California.
usbcore: registered new interface driver ax88179_178a
usbcore: registered new interface driver cdc_ether
usbcore: registered new interface driver net1080
usbcore: registered new interface driver cdc_subset
usbcore: registered new interface driver cdc_ncm
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ehci-pci: EHCI PCI platform driver
usbcore: registered new interface driver cdc_acm
cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: registered as rtc0
i2c /dev entries driver
qcom-smbb fc4cf000.spmi:pm8941@0:charger@1000: Initializing SMBB rev 3
otg-vbus: supplied by 5vs1
cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
sdhci: Secure Digital Host Controller Interface driver
sdhci: Copyright(c) Pierre Ossman
sdhci-pltfm: SDHCI platform and OF driver helper
sdhci_msm f98a4900.sdhci: Got CD GPIO
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
oprofile: using timer interrupt.
NET: Registered protocol family 17
Key type dns_resolver registered
Registering SWP/SWPB emulation handler
Loading compiled-in X.509 certificates
debugfs: Directory 'fc4a9000.thermal-sensor' with parent 'tsens' already present!
s1: supplied by regulator-dummy
s1: Bringing 0uV into 675000-675000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
s2: supplied by regulator-dummy
s2: Bringing 0uV into 500000-500000uV
s3: supplied by regulator-dummy
ocmem fdd00000.ocmem: 8 ports, 3 regions, 2048 macros, interleaved
s3: Bringing 0uV into 500000-500000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
s4: supplied by regulator-dummy
s4: Bringing 0uV into 500000-500000uV
s5: supplied by regulator-dummy
sdhci_msm f98a4900.sdhci: Got CD GPIO
rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-07T19:24:17 UTC (3266657)
-> ### dt-test ### start of unittest - you will see error messages
s6: supplied by regulator-dummy
ok Duplicate name in testcase-data, renamed to "duplicate-name#1"
s7: supplied by regulator-dummy
s8: supplied by regulator-dummy
ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
s1: supplied by regulator-dummy
ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
s1: Bringing 0uV into 1300000-1300000uV
s2: supplied by regulator-dummy
ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
sdhci_msm f98a4900.sdhci: Got CD GPIO
ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
s2: Bringing 0uV into 2150000-2150000uV
s3: supplied by regulator-dummy
ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
s3: Bringing 0uV into 1800000-1800000uV
ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
l1: supplied by s1
ok OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
l1: Bringing 0uV into 1225000-1225000uV
ok OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
l2: supplied by s3
l2: Bringing 0uV into 1200000-1200000uV
ok OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
l3: supplied by s1
l3: Bringing 0uV into 1225000-1225000uV
ok platform testcase-data:testcase-device2: IRQ index 0 not found
l4: supplied by s1
l4: Bringing 0uV into 1225000-1225000uV
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
l5: supplied by s2
l5: Bringing 0uV into 1800000-1800000uV
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
l6: supplied by s2
l6: Bringing 0uV into 1800000-1800000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l7: supplied by s2
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
l7: Bringing 0uV into 1800000-1800000uV
l8: supplied by regulator-dummy
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
l8: Bringing 0uV into 1800000-1800000uV
l9: supplied by regulator-dummy
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
l9: Bringing 0uV into 1800000-1800000uV
l10: supplied by regulator-dummy
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
l10: Bringing 0uV into 1800000-1800000uV
l11: supplied by s1
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
l11: Bringing 0uV into 1300000-1300000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l12: supplied by s2
l12: Bringing 0uV into 1800000-1800000uV
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
l13: supplied by regulator-dummy
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
sdhci_msm f98a4900.sdhci: Got CD GPIO
l13: Bringing 0uV into 1800000-1800000uV
ok OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
ok OF: overlay: overlay #6 is not topmost
l14: supplied by s2
l14: Bringing 0uV into 1800000-1800000uV
l15: supplied by s2
ok i2c i2c-1: Added multiplexed i2c bus 2
l15: Bringing 0uV into 2050000-2050000uV
l16: supplied by regulator-dummy
sdhci_msm f98a4900.sdhci: Got CD GPIO
l16: Bringing 0uV into 2700000-2700000uV
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
l17: supplied by regulator-dummy
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
l17: Bringing 0uV into 2700000-2700000uV
l18: supplied by regulator-dummy
ok i2c i2c-1: Added multiplexed i2c bus 3
l18: Bringing 0uV into 2850000-2850000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l19: supplied by regulator-dummy
l19: Bringing 0uV into 3300000-3300000uV
l20: supplied by regulator-dummy
ok GPIO line 315 (line-B-input) hogged as input
l20: Bringing 0uV into 2950000-2950000uV
ok GPIO line 309 (line-A-input) hogged as input
l21: supplied by regulator-dummy
l21: Bringing 0uV into 2950000-2950000uV
l22: supplied by regulator-dummy
ok GPIO line 307 (line-D-input) hogged as input
l22: Bringing 0uV into 3000000-3000000uV
l23: supplied by regulator-dummy
l23: Bringing 0uV into 3000000-3000000uV
** of_unittest_expect WARNING - not found ---> GPIO line <<int>> (line-C-input) hogged as input
l24: supplied by regulator-dummy
mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA
l24: Bringing 0uV into 3075000-3075000uV
>> ### dt-test ### FAIL of_unittest_overlay_gpio():2664 unittest_gpio_chip_request() called 0 times (expected 1 time)
lvs1: supplied by s3
lvs2: supplied by s3
sdhci_msm f98a4900.sdhci: Got CD GPIO
lvs3: supplied by s3
5vs1: supplied by s4
5vs2: supplied by s4
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
msm_hsusb f9a55000.usb: failed to create device link to ci_hdrc.0.ulpi
ok OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
mmc1: new ultra high speed DDR50 SDHC card at address aaaa
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
mmcblk1: mmc1:aaaa SU16G 14.8 GiB
ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail
mmcblk1: p1
-> ### dt-test ### end of unittest - 258 passed, 1 failed
ALSA device list:
No soundc�[ 4.382470] Freeing unused kernel memory: 1024K
mmcblk0: mmc0:0001 SEM16G 14.7 GiB
mmcblk0boot0: mmc0:0001 SEM16G partition 1 4.00 MiB
mmcblk0boot1: mmc0:0001 SEM16G partition 2 4.00 MiB
mmcblk0rpmb: mmc0:0001 SEM16G partition 3 4.00 MiB, chardev (247:0)
Run /init as init process
mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20
mkdir: can't create directory '/bin': File exists
mkdir: can't create directory '/dev': File exists
/init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory
mdev: unknown user/group 'root:uucp' on line 34
Attempt to mount partitions: /usr/system /usr/data
Mounting partitions from: /dev/mmcblk0
EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Opts: (null)
EXT4-fs (mmcblk0p13): recovery complete
EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Opts: (null)
/ # [ 5.288283] random: fast init done

/ # cat /proc/version
Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020
/ #

** EXPECT statistics:
**
** EXPECT found : 45
** EXPECT not found : 1
** missing EXPECT begin : 0
** missing EXPECT end : 0
** unittest FAIL : 1
** internal error : 0

2022-02-02 23:35:36

by Frank Rowand

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

On 2/1/22 12:14 PM, [email protected] wrote:
> From: Frank Rowand <[email protected]>
>

< snip >

>
> I will also reply with examples of raw and processed console logs.

< snip >

In 5.17-rc1 some error messages triggered by unittest changed.
This is the raw console log that showed the problem.

$ cat console_01
Android Bootloader - UART_DM Initialized!!!
[0] welcome to lk

[10] platform_init()
[10] target_init()
[10] Display Init: Start
[10] display_init(),target_id=10.
[30] Config MIPI_VIDEO_PANEL.
[30] Turn on MIPI_VIDEO_PANEL.
[50] Video lane tested successfully
[50] Display Init: Done
[80] Loading keystore failed status 5 [80] ERROR: scm_protect_keystore Failed[200] USB init ept @ 0xf96b000
[220] fastboot_init()
[220] udc_start()
[360] -- reset --
[360] -- portchange --
[500] -- reset --
[500] -- portchange --
[660] fastboot: processing commands
[670] fastboot: getvar:slot-count
[670] fastboot: getvar:slot-suffixes
[690] fastboot: download:01086800
[1220] fastboot: boot
[1240] Found Appeneded Flattened Device tree
[1250] cmdline: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
[1260] Updating device tree: start
[1270] Updating device tree: done
[1270] booting linux @ 0x8000, ramdisk @ 0x2000000 (9533134), tags/device tree @ 0x1e00000
[1280] Turn off MIPI_VIDEO_PANEL.
[1280] Continuous splash enabled, keeping panel alive.
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 5.17.0-rc1 (frowand@xps8900) (arm-linux-gnueabi-gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #2 SMP PREEMPT Wed Jan 26 20:17:12 CST 2022
[ 0.000000] CPU: ARMv7 Processor [512f06f0] revision 0 (ARMv7), cr=10c5787d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[ 0.000000] OF: fdt: Machine model: Qualcomm APQ8074 Dragonboard
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 64 MiB at 0x7c000000
[ 0.000000] Zone ranges:
[ 0.000000] Normal [mem 0x0000000000000000-0x000000002fffffff]
[ 0.000000] HighMem [mem 0x0000000030000000-0x000000007fffffff]
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000000000-0x0000000007ffffff]
[ 0.000000] node 0: [mem 0x0000000008000000-0x000000000fefffff]
[ 0.000000] node 0: [mem 0x000000000ff00000-0x000000007fffffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000007fffffff]
[ 0.000000] percpu: Embedded 16 pages/cpu s33100 r8192 d24244 u65536
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 522752
[ 0.000000] Kernel command line: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] Memory: 1855444K/2097152K available (11264K kernel code, 1548K rwdata, 4692K rodata, 1024K init, 251K bss, 176172K reserved, 65536K cma-reserved, 1245184K highmem)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] trace event string verifier disabled
[ 0.000000] rcu: Preemptible hierarchical RCU implementation.
[ 0.000000] rcu: RCU event tracing is enabled.
[ 0.000000] Trampoline variant of Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] random: get_random_bytes called from start_kernel+0x4f4/0x69c with crng_init=0
[ 0.000000] arch_timer: cp15 and mmio timer(s) running at 19.20MHz (virt/virt).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000001] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000019] Switching to timer-based delay loop, resolution 52ns
[ 0.000430] Console: colour dummy device 80x30
[ 0.000480] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000503] pid_max: default: 32768 minimum: 301
[ 0.000621] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.000642] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.001203] CPU: Testing write buffer coherency: ok
[ 0.001445] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.001474] qcom_scm: convention: smc legacy
[ 0.002046] cblist_init_generic: Setting adjustable number of callback queues.
[ 0.002063] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.002174] Setting up static identity map for 0x300000 - 0x300060
[ 0.002298] rcu: Hierarchical SRCU implementation.
[ 0.003303] smp: Bringing up secondary CPUs ...
[ 0.004052] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.004238] smp: Brought up 1 node, 2 CPUs
[ 0.004259] SMP: Total of 2 processors activated (76.80 BogoMIPS).
[ 0.004273] CPU: All CPU(s) started in SVC mode.
[ 0.004942] devtmpfs: initialized
[ 0.013762] VFP support v0.3: implementor 51 architecture 64 part 6f variant 2 rev 0
[ 0.013970] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.013996] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[ 0.016614] pinctrl core: initialized pinctrl subsystem
[ 0.017641] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[ 0.019550] DMA: preallocated 256 KiB pool for atomic coherent allocations
[ 0.020812] thermal_sys: Registered thermal governor 'step_wise'
[ 0.022084] cpuidle: using governor menu
[ 0.022514] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.022532] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.059997] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
[ 0.062048] iommu: Default domain type: Translated
[ 0.062063] iommu: DMA domain TLB invalidation policy: strict mode
[ 0.062384] vgaarb: loaded
[ 0.062827] SCSI subsystem initialized
[ 0.063230] usbcore: registered new interface driver usbfs
[ 0.063291] usbcore: registered new interface driver hub
[ 0.063344] usbcore: registered new device driver usb
[ 0.063453] mc: Linux media interface: v0.10
[ 0.063501] videodev: Linux video capture interface: v2.00
[ 0.063556] pps_core: LinuxPPS API ver. 1 registered
[ 0.063569] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>
[ 0.063596] PTP clock support registered
[ 0.064469] Advanced Linux Sound Architecture Driver Initialized.
[ 0.065579] clocksource: Switched to clocksource arch_sys_counter
[ 0.147254] NET: Registered PF_INET protocol family
[ 0.147479] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[ 0.148878] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[ 0.148918] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[ 0.148989] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[ 0.149119] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.149235] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.149280] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.149476] NET: Registered PF_UNIX/PF_LOCAL protocol family
[ 0.149993] RPC: Registered named UNIX socket transport module.
[ 0.150013] RPC: Registered udp transport module.
[ 0.150029] RPC: Registered tcp transport module.
[ 0.150043] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.150062] PCI: CLS 0 bytes, default 64
[ 0.150799] hw perfevents: enabled with armv7_krait PMU driver, 5 counters available
[ 0.152702] Initialise system trusted keyrings
[ 0.153119] Trying to unpack rootfs image as initramfs...
[ 0.165654] workingset: timestamp_bits=30 max_order=19 bucket_order=0
[ 0.186121] NFS: Registering the id_resolver key type
[ 0.186169] Key type id_resolver registered
[ 0.186189] Key type id_legacy registered
[ 0.236014] Key type cifs.idmap registered
[ 0.236052] jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
[ 0.236432] fuse: init (API version 7.36)
[ 0.236930] Key type asymmetric registered
[ 0.236951] Asymmetric key parser 'x509' registered
[ 0.237148] bounce: pool size: 64 pages
[ 0.237306] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
[ 0.237327] io scheduler mq-deadline registered
[ 0.237344] io scheduler kyber registered
[ 0.305925] msm_serial f991e000.serial: msm_serial: detected port #0
[ 0.305987] msm_serial f991e000.serial: uartclk = 7372800
[ 0.306057] f991e000.serial: ttyMSM0 at MMIO 0xf991e000 (irq = 36, base_baud = 460800) is a MSM
[ 0.306105] msm_serial: console setup on port #0
[ 1.065075] Freeing initrd memory: 9312K
[ 1.068273] printk: console [ttyMSM0] enabled
[ 1.113852] msm_serial: driver initialized
[ 1.130672] brd: module loaded
[ 1.134949] loop: module loaded
[ 1.135411] SCSI Media Changer driver v0.25
[ 1.137951] spmi spmi-0: PMIC arbiter version v1 (0x20000002)
[ 1.157702] SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256) (6 bit encapsulation enabled).
[ 1.157739] CSLIP: code copyright 1989 Regents of the University of California.
[ 1.166324] usbcore: registered new interface driver ax88179_178a
[ 1.173487] usbcore: registered new interface driver cdc_ether
[ 1.179763] usbcore: registered new interface driver net1080
[ 1.185465] usbcore: registered new interface driver cdc_subset
[ 1.191324] usbcore: registered new interface driver cdc_ncm
[ 1.197785] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 1.202791] ehci-pci: EHCI PCI platform driver
[ 1.209241] usbcore: registered new interface driver cdc_acm
[ 1.213553] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[ 1.222533] rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: registered as rtc0
[ 1.227168] rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-15T05:42:10 UTC (3908530)
[ 1.234158] i2c_dev: i2c /dev entries driver
[ 1.247147] /cpus/cpu@0: unsupported enable-method property: qcom,kpss-acc-v2
[ 1.249100] sdhci: Secure Digital Host Controller Interface driver
[ 1.255766] sdhci: Copyright(c) Pierre Ossman
[ 1.261816] sdhci-pltfm: SDHCI platform and OF driver helper
[ 1.267020] usbcore: registered new interface driver usbhid
[ 1.271973] usbhid: USB HID core driver
[ 1.278875] extcon-pm8941-misc fc4cf000.spmi:pm8941@0:misc@900: IRQ usb_vbus not found
[ 1.281528] SPI driver bmp280 has no spi_device_id for bosch,bmp085
[ 1.291260] NET: Registered PF_PACKET protocol family
[ 1.295300] Key type dns_resolver registered
[ 1.300702] Registering SWP/SWPB emulation handler
[ 1.304979] Loading compiled-in X.509 certificates
[ 1.327250] s4: Bringing 5100000uV into 5000000-5000000uV
[ 1.337863] s1: Bringing 0uV into 675000-675000uV
[ 1.338182] s2: Bringing 0uV into 500000-500000uV
[ 1.341996] s3: Bringing 0uV into 500000-500000uV
[ 1.342333] qcom-smbb fc4cf000.spmi:pm8941@0:charger@1000: Initializing SMBB rev 3
[ 1.346559] s4: Bringing 0uV into 500000-500000uV
[ 1.361204] s1: Bringing 0uV into 1300000-1300000uV
[ 1.365357] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 1.365874] qcom_q6v5_pas adsp-pil: supply px not found, using dummy regulator
[ 1.368369] s2: Bringing 0uV into 2150000-2150000uV
[ 1.373477] remoteproc remoteproc0: adsp-pil is available
[ 1.384745] remoteproc remoteproc0: Direct firmware load for adsp.mdt failed with error -2
[ 1.384897] s3: Bringing 0uV into 1800000-1800000uV
[ 1.390265] remoteproc remoteproc0: powering up adsp-pil
[ 1.403419] l1: Bringing 0uV into 1225000-1225000uV
[ 1.403614] remoteproc remoteproc0: Direct firmware load for adsp.mdt failed with error -2
[ 1.413737] ocmem fdd00000.ocmem: 8 ports, 3 regions, 2048 macros, interleaved
[ 1.414008] l2: Bringing 0uV into 1200000-1200000uV
[ 1.421623] remoteproc remoteproc0: request_firmware failed: -2
[ 1.429138] l3: Bringing 0uV into 1225000-1225000uV
[ 1.439789] l4: Bringing 0uV into 1225000-1225000uV
[ 1.444631] l5: Bringing 0uV into 1800000-1800000uV
[ 1.449699] l6: Bringing 0uV into 1800000-1800000uV
[ 1.455040] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 1.460140] l7: Bringing 0uV into 1800000-1800000uV
[ 1.464271] l8: Bringing 0uV into 1800000-1800000uV
[ 1.469727] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 1.474076] l9: Bringing 0uV into 1800000-1800000uV
[ 1.478612] l10: Bringing 0uV into 1800000-1800000uV
[ 1.483650] l11: Bringing 0uV into 1300000-1300000uV
[ 1.488520] l12: Bringing 0uV into 1800000-1800000uV
[ 1.488604] ### dt-test ### start of unittest - you will see error messages
[ 1.498316] l13: Bringing 0uV into 1800000-1800000uV
[ 1.498950] ### dt-test ### EXPECT \ : Duplicate name in testcase-data, renamed to "duplicate-name#1"
[ 1.504798] Duplicate name in testcase-data, renamed to "duplicate-name#1"
[ 1.519177] l14: Bringing 0uV into 1800000-1800000uV
[ 1.521907] ### dt-test ### EXPECT / : Duplicate name in testcase-data, renamed to "duplicate-name#1"
[ 1.526164] l15: Bringing 0uV into 2050000-2050000uV
[ 1.526528] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 1.531219] l16: Bringing 0uV into 2700000-2700000uV
[ 1.540003] OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 1.545448] l17: Bringing 0uV into 2700000-2700000uV
[ 1.559357] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 1.559365] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 1.559373] OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 1.565011] l18: Bringing 0uV into 2850000-2850000uV
[ 1.576812] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 1.576820] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 1.582194] l19: Bringing 0uV into 3300000-3300000uV
[ 1.596117] OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
[ 1.623492] l20: Bringing 0uV into 2950000-2950000uV
[ 1.628122] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 1.628129] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 1.628163] OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
[ 1.652474] l21: Bringing 0uV into 2950000-2950000uV
[ 1.657277] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 1.657285] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 1.657294] OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
[ 1.670630] l22: Bringing 0uV into 3000000-3000000uV
[ 1.679760] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 1.679768] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 1.679777] OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
[ 1.689865] l23: Bringing 0uV into 3000000-3000000uV
[ 1.697636] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 1.697800] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
[ 1.703025] l24: Bringing 0uV into 3075000-3075000uV
[ 1.712062] OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
[ 1.797263] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
[ 1.797272] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
[ 1.809523] OF: /testcase-data/phandle-tests/consumer-b: could not find phandle 12345678
[ 1.814002] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 1.823785] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
[ 1.841783] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
[ 1.846442] OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found 1
[ 1.866014] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
[ 1.868211] ### dt-test ### EXPECT \ : platform testcase-data:testcase-device2: IRQ index 0 not found
[ 1.873501] platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
[ 1.875619] mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA
[ 1.883615] ### dt-test ### EXPECT / : platform testcase-data:testcase-device2: IRQ index 0 not found
[ 1.904844] genirq: irq_chip msmgpio did not update eff. affinity mask of irq 72
[ 1.904899] ### dt-test ### end of unittest - 187 passed, 0 failed
[ 1.908636] mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA
[ 1.918522] ALSA device�[ 1.943228] Freeing unused kernel image (initmem) memory: 1024K
[ 1.976357] mmc0: new HS200 MMC card at address 0001
[ 1.976965] mmcblk0: mmc0:0001 SEM16G 14.7 GiB
[ 1.982938] mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20
[ 1.985753] Run /init as init process
[ 1.988318] mmcblk0boot0: mmc0:0001 SEM16G 4.00 MiB
[ 1.998330] mmcblk0boot1: mmc0:0001 SEM16G 4.00 MiB
[ 2.002099] mmc1: new ultra high speed DDR50 SDHC card at address aaaa
[ 2.008049] mmcblk0rpmb: mmc0:0001 SEM16G 4.00 MiB, chardev (243:0)
[ 2.013504] mmcblk1: mmc1:aaaa SU16G 14.8 GiB
mkdir: can't create directory '/bin': File exists
[ 2.023994] mmcblk1: p1
mkdir: can't create directory '/dev': File exists
mount: mounting debugfs on /debugfs failed: No such device
/init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory
mdev: unknown user/group 'root:uucp' on line 34
Attempt to mount partitions: /usr/system /usr/data
Mounting partitions from: /dev/mmcblk0
[ 2.585300] random: fast init done
[ 2.589625] EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Quota mode: disabled.
[ 2.670478] EXT4-fs (mmcblk0p13): recovery complete
[ 2.671254] EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Quota mode: disabled.
/ # cat /proc/version
Linux version 5.17.0-rc1 (frowand@xps8900) (arm-linux-gnueabi-gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #2 SMP PREEMPT Wed Jan 26 20:17:12 CST 2022

2022-02-03 20:51:45

by Frank Rowand

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

On 2/1/22 12:14 PM, [email protected] wrote:
> From: Frank Rowand <[email protected]>
>

< snip >

> I will also reply with examples of raw and processed console logs.

< snip >

In 5.17-rc1 some error messages triggered by unittest changed.
This is the raw console log that showed the problem, filtered
by of_unittest_expect.

Note the lines prefixed with '** ' that report that expected
error messages were not found.

Note the summary at the end of the output:

** EXPECT statistics:
**
** EXPECT found : 7
** EXPECT not found : 4


$ scripts/dtc/of_unittest_expect console_01
Android Bootloader - UART_DM Initialized!!!
[0] welcome to lk

[10] platform_init()
[10] target_init()
[10] Display Init: Start
[10] display_init(),target_id=10.
[30] Config MIPI_VIDEO_PANEL.
[30] Turn on MIPI_VIDEO_PANEL.
[50] Video lane tested successfully
[50] Display Init: Done
[80] Loading keystore failed status 5 [80] ERROR: scm_protect_keystore Failed[200] USB init ept @ 0xf96b000
[220] fastboot_init()
[220] udc_start()
[360] -- reset --
[360] -- portchange --
[500] -- reset --
[500] -- portchange --
[660] fastboot: processing commands
[670] fastboot: getvar:slot-count
[670] fastboot: getvar:slot-suffixes
[690] fastboot: download:01086800
[1220] fastboot: boot
[1240] Found Appeneded Flattened Device tree
[1250] cmdline: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
[1260] Updating device tree: start
[1270] Updating device tree: done
[1270] booting linux @ 0x8000, ramdisk @ 0x2000000 (9533134), tags/device tree @ 0x1e00000
[1280] Turn off MIPI_VIDEO_PANEL.
[1280] Continuous splash enabled, keeping panel alive.
Booting Linux on physical CPU 0x0
Linux version 5.17.0-rc1 (frowand@xps8900) (arm-linux-gnueabi-gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #2 SMP PREEMPT Wed Jan 26 20:17:12 CST 2022
CPU: ARMv7 Processor [512f06f0] revision 0 (ARMv7), cr=10c5787d
CPU: div instructions available: patching division code
CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
OF: fdt: Machine model: Qualcomm APQ8074 Dragonboard
Memory policy: Data cache writealloc
cma: Reserved 64 MiB at 0x7c000000
Zone ranges:
Normal [mem 0x0000000000000000-0x000000002fffffff]
HighMem [mem 0x0000000030000000-0x000000007fffffff]
Movable zone start for each node
Early memory node ranges
node 0: [mem 0x0000000000000000-0x0000000007ffffff]
node 0: [mem 0x0000000008000000-0x000000000fefffff]
node 0: [mem 0x000000000ff00000-0x000000007fffffff]
Initmem setup node 0 [mem 0x0000000000000000-0x000000007fffffff]
percpu: Embedded 16 pages/cpu s33100 r8192 d24244 u65536
Built 1 zonelists, mobility grouping on. Total pages: 522752
Kernel command line: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
mem auto-init: stack:off, heap alloc:off, heap free:off
Memory: 1855444K/2097152K available (11264K kernel code, 1548K rwdata, 4692K rodata, 1024K init, 251K bss, 176172K reserved, 65536K cma-reserved, 1245184K highmem)
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
trace event string verifier disabled
rcu: Preemptible hierarchical RCU implementation.
rcu: RCU event tracing is enabled.
Trampoline variant of Tasks RCU enabled.
rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
random: get_random_bytes called from start_kernel+0x4f4/0x69c with crng_init=0
arch_timer: cp15 and mmio timer(s) running at 19.20MHz (virt/virt).
clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
Switching to timer-based delay loop, resolution 52ns
Console: colour dummy device 80x30
Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
qcom_scm: convention: smc legacy
cblist_init_generic: Setting adjustable number of callback queues.
cblist_init_generic: Setting shift to 2 and lim to 1.
Setting up static identity map for 0x300000 - 0x300060
rcu: Hierarchical SRCU implementation.
smp: Bringing up secondary CPUs ...
CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
smp: Brought up 1 node, 2 CPUs
SMP: Total of 2 processors activated (76.80 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
VFP support v0.3: implementor 51 architecture 64 part 6f variant 2 rev 0
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
pinctrl core: initialized pinctrl subsystem
NET: Registered PF_NETLINK/PF_ROUTE protocol family
DMA: preallocated 256 KiB pool for atomic coherent allocations
thermal_sys: Registered thermal governor 'step_wise'
cpuidle: using governor menu
hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 8 bytes.
kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
iommu: Default domain type: Translated
iommu: DMA domain TLB invalidation policy: strict mode
vgaarb: loaded
SCSI subsystem initialized
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
mc: Linux media interface: v0.10
videodev: Linux video capture interface: v2.00
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>
PTP clock support registered
Advanced Linux Sound Architecture Driver Initialized.
clocksource: Switched to clocksource arch_sys_counter
NET: Registered PF_INET protocol family
IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
TCP: Hash tables configured (established 8192 bind 8192)
UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
NET: Registered PF_UNIX/PF_LOCAL protocol family
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
PCI: CLS 0 bytes, default 64
hw perfevents: enabled with armv7_krait PMU driver, 5 counters available
Initialise system trusted keyrings
Trying to unpack rootfs image as initramfs...
workingset: timestamp_bits=30 max_order=19 bucket_order=0
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
Key type cifs.idmap registered
jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
fuse: init (API version 7.36)
Key type asymmetric registered
Asymmetric key parser 'x509' registered
bounce: pool size: 64 pages
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
io scheduler mq-deadline registered
io scheduler kyber registered
msm_serial f991e000.serial: msm_serial: detected port #0
msm_serial f991e000.serial: uartclk = 7372800
f991e000.serial: ttyMSM0 at MMIO 0xf991e000 (irq = 36, base_baud = 460800) is a MSM
msm_serial: console setup on port #0
Freeing initrd memory: 9312K
printk: console [ttyMSM0] enabled
msm_serial: driver initialized
brd: module loaded
loop: module loaded
SCSI Media Changer driver v0.25
spmi spmi-0: PMIC arbiter version v1 (0x20000002)
SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256) (6 bit encapsulation enabled).
CSLIP: code copyright 1989 Regents of the University of California.
usbcore: registered new interface driver ax88179_178a
usbcore: registered new interface driver cdc_ether
usbcore: registered new interface driver net1080
usbcore: registered new interface driver cdc_subset
usbcore: registered new interface driver cdc_ncm
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ehci-pci: EHCI PCI platform driver
usbcore: registered new interface driver cdc_acm
cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: registered as rtc0
rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-15T05:42:10 UTC (3908530)
i2c_dev: i2c /dev entries driver
/cpus/cpu@0: unsupported enable-method property: qcom,kpss-acc-v2
sdhci: Secure Digital Host Controller Interface driver
sdhci: Copyright(c) Pierre Ossman
sdhci-pltfm: SDHCI platform and OF driver helper
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
extcon-pm8941-misc fc4cf000.spmi:pm8941@0:misc@900: IRQ usb_vbus not found
SPI driver bmp280 has no spi_device_id for bosch,bmp085
NET: Registered PF_PACKET protocol family
Key type dns_resolver registered
Registering SWP/SWPB emulation handler
Loading compiled-in X.509 certificates
s4: Bringing 5100000uV into 5000000-5000000uV
s1: Bringing 0uV into 675000-675000uV
s2: Bringing 0uV into 500000-500000uV
s3: Bringing 0uV into 500000-500000uV
qcom-smbb fc4cf000.spmi:pm8941@0:charger@1000: Initializing SMBB rev 3
s4: Bringing 0uV into 500000-500000uV
s1: Bringing 0uV into 1300000-1300000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
qcom_q6v5_pas adsp-pil: supply px not found, using dummy regulator
s2: Bringing 0uV into 2150000-2150000uV
remoteproc remoteproc0: adsp-pil is available
remoteproc remoteproc0: Direct firmware load for adsp.mdt failed with error -2
s3: Bringing 0uV into 1800000-1800000uV
remoteproc remoteproc0: powering up adsp-pil
l1: Bringing 0uV into 1225000-1225000uV
remoteproc remoteproc0: Direct firmware load for adsp.mdt failed with error -2
ocmem fdd00000.ocmem: 8 ports, 3 regions, 2048 macros, interleaved
l2: Bringing 0uV into 1200000-1200000uV
remoteproc remoteproc0: request_firmware failed: -2
l3: Bringing 0uV into 1225000-1225000uV
l4: Bringing 0uV into 1225000-1225000uV
l5: Bringing 0uV into 1800000-1800000uV
l6: Bringing 0uV into 1800000-1800000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l7: Bringing 0uV into 1800000-1800000uV
l8: Bringing 0uV into 1800000-1800000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l9: Bringing 0uV into 1800000-1800000uV
l10: Bringing 0uV into 1800000-1800000uV
l11: Bringing 0uV into 1300000-1300000uV
l12: Bringing 0uV into 1800000-1800000uV
-> ### dt-test ### start of unittest - you will see error messages
l13: Bringing 0uV into 1800000-1800000uV
ok Duplicate name in testcase-data, renamed to "duplicate-name#1"
l14: Bringing 0uV into 1800000-1800000uV
l15: Bringing 0uV into 2050000-2050000uV
l16: Bringing 0uV into 2700000-2700000uV
ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
l17: Bringing 0uV into 2700000-2700000uV
ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
l18: Bringing 0uV into 2850000-2850000uV
l19: Bringing 0uV into 3300000-3300000uV
ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
l20: Bringing 0uV into 2950000-2950000uV
ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle 12345678
l21: Bringing 0uV into 2950000-2950000uV
OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
l22: Bringing 0uV into 3000000-3000000uV
** of_unittest_expect WARNING - not found ---> OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found 1
l23: Bringing 0uV into 3000000-3000000uV
** of_unittest_expect WARNING - not found ---> OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
l24: Bringing 0uV into 3075000-3075000uV
ok OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
ok OF: /testcase-data/phandle-tests/consumer-b: could not find phandle 12345678
sdhci_msm f98a4900.sdhci: Got CD GPIO
OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found 1
** of_unittest_expect WARNING - not found ---> OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA
** of_unittest_expect WARNING - not found ---> platform testcase-data:testcase-device2: IRQ index 0 not found
genirq: irq_chip msmgpio did not update eff. affinity mask of irq 72
-> ### dt-test ### end of unittest - 187 passed, 0 failed
mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA
ALSA device�[ 1.943228] Freeing unused kernel image (initmem) memory: 1024K
mmc0: new HS200 MMC card at address 0001
mmcblk0: mmc0:0001 SEM16G 14.7 GiB
mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20
Run /init as init process
mmcblk0boot0: mmc0:0001 SEM16G 4.00 MiB
mmcblk0boot1: mmc0:0001 SEM16G 4.00 MiB
mmc1: new ultra high speed DDR50 SDHC card at address aaaa
mmcblk0rpmb: mmc0:0001 SEM16G 4.00 MiB, chardev (243:0)
mmcblk1: mmc1:aaaa SU16G 14.8 GiB
mkdir: can't create directory '/bin': File exists
mmcblk1: p1
mkdir: can't create directory '/dev': File exists
mount: mounting debugfs on /debugfs failed: No such device
/init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory
mdev: unknown user/group 'root:uucp' on line 34
Attempt to mount partitions: /usr/system /usr/data
Mounting partitions from: /dev/mmcblk0
random: fast init done
EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Quota mode: disabled.
EXT4-fs (mmcblk0p13): recovery complete
EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Quota mode: disabled.
/ # cat /proc/version
Linux version 5.17.0-rc1 (frowand@xps8900) (arm-linux-gnueabi-gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #2 SMP PREEMPT Wed Jan 26 20:17:12 CST 2022
/ #

** EXPECT statistics:
**
** EXPECT found : 7
** EXPECT not found : 4
** missing EXPECT begin : 0
** missing EXPECT end : 0
** unittest FAIL : 0
** internal error : 0

2022-02-04 08:52:37

by Frank Rowand

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

On 2/1/22 12:14 PM, [email protected] wrote:
> From: Frank Rowand <[email protected]>
>

< snip >

>
> I will also reply with examples of raw and processed console logs.

< snip >

In 5.6-rc1 there was a problem with the test of gpio hogs. This is
the raw console log that showed the problem.

$ cat ../linux--5.6-rc/console_gpio_unittest
Android Bootloader - UART_DM Initialized!!!
[0] welcome to lk

[10] platform_init()
[10] target_init()
[10] Display Init: Start
[10] display_init(),target_id=10.
[30] Config MIPI_VIDEO_PANEL.
[30] Turn on MIPI_VIDEO_PANEL.
[50] Video lane tested successfully
[50] Display Init: Done
[80] Loading keystore failed status 5 [80] ERROR: scm_protect_keystore Failed[200] USB init ept @ 0xf96b000
[220] fastboot_init()
[220] udc_start()
[350] -- reset --
[350] -- portchange --
[460] -- reset --
[460] -- portchange --
[650] fastboot: processing commands
[760] fastboot: download:00f3f800
[1250] fastboot: boot
[1260] Found Appeneded Flattened Device tree
[1270] cmdline: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
[1290] Updating device tree: start
[1290] Updating device tree: done
[1300] booting linux @ 0x8000, ramdisk @ 0x2000000 (9533134), tags/device tree @ 0x1e00000
[1300] Turn off MIPI_VIDEO_PANEL.
[1300] Continuous splash enabled, keeping panel alive.
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020
[ 0.000000] CPU: ARMv7 Processor [512f06f0] revision 0 (ARMv7), cr=10c5787d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[ 0.000000] OF: fdt: Machine model: Qualcomm APQ8074 Dragonboard
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 256 MiB at 0x70000000
[ 0.000000] percpu: Embedded 19 pages/cpu s48256 r8192 d21376 u77824
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 490240
[ 0.000000] Kernel command line: console=ttyMSM0,115200,n8 androidboot.hardware=qcom maxcpus=2 msm_rtb.filter=0x37 ehci-hcd.park=3 norandmaps androidboot.emmc=true androidboot.serialno=40081c41 androidboot.baseband=apq
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] Memory: 1662424K/1967104K available (9216K kernel code, 946K rwdata, 3852K rodata, 1024K init, 269K bss, 42536K reserved, 262144K cma-reserved, 1048576K highmem)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] rcu: Preemptible hierarchical RCU implementation.
[ 0.000000] rcu: RCU event tracing is enabled.
[ 0.000000] Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] random: get_random_bytes called from start_kernel+0x52c/0x76c with crng_init=0
[ 0.000000] arch_timer: cp15 and mmio timer(s) running at 19.20MHz (virt/virt).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000005] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000016] Switching to timer-based delay loop, resolution 52ns
[ 0.000425] Console: colour dummy device 80x30
[ 0.000457] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000471] pid_max: default: 32768 minimum: 301
[ 0.000603] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.000620] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.001219] CPU: Testing write buffer coherency: ok
[ 0.001503] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.001525] qcom_scm: convention: smc legacy
[ 0.059946] Setting up static identity map for 0x300000 - 0x300060
[ 0.079947] rcu: Hierarchical SRCU implementation.
[ 0.120028] smp: Bringing up secondary CPUs ...
[ 0.200490] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.200699] smp: Brought up 1 node, 2 CPUs
[ 0.200714] SMP: Total of 2 processors activated (76.80 BogoMIPS).
[ 0.200722] CPU: All CPU(s) started in SVC mode.
[ 0.201334] devtmpfs: initialized
[ 0.210578] VFP support v0.3: implementor 51 architecture 64 part 6f variant 2 rev 0
[ 0.210937] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.210957] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[ 0.220811] pinctrl core: initialized pinctrl subsystem
[ 0.221680] thermal_sys: Registered thermal governor 'step_wise'
[ 0.223264] NET: Registered protocol family 16
[ 0.224749] DMA: preallocated 256 KiB pool for atomic coherent allocations
[ 0.226015] cpuidle: using governor menu
[ 0.226397] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.226409] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.264195] iommu: Default domain type: Translated
[ 0.264493] vgaarb: loaded
[ 0.264996] SCSI subsystem initialized
[ 0.265460] usbcore: registered new interface driver usbfs
[ 0.265527] usbcore: registered new interface driver hub
[ 0.265615] usbcore: registered new device driver usb
[ 0.265976] qcom_scm: convention: smc legacy
[ 0.266643] Advanced Linux Sound Architecture Driver Initialized.
[ 0.267589] clocksource: Switched to clocksource arch_sys_counter
[ 0.703278] NET: Registered protocol family 2
[ 0.703747] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[ 0.703772] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[ 0.703832] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[ 0.703919] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.704011] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.704038] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.704190] NET: Registered protocol family 1
[ 0.704766] RPC: Registered named UNIX socket transport module.
[ 0.704777] RPC: Registered udp transport module.
[ 0.704786] RPC: Registered tcp transport module.
[ 0.704795] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.704809] PCI: CLS 0 bytes, default 64
[ 0.705072] Trying to unpack rootfs image as initramfs...
[ 1.255915] Freeing initrd memory: 9312K
[ 1.256509] hw perfevents: enabled with armv7_krait PMU driver, 5 counters available
[ 1.258217] Initialise system trusted keyrings
[ 1.258416] workingset: timestamp_bits=30 max_order=19 bucket_order=0
[ 1.264805] NFS: Registering the id_resolver key type
[ 1.264829] Key type id_resolver registered
[ 1.264840] Key type id_legacy registered
[ 1.265772] Key type cifs.idmap registered
[ 1.265789] jffs2: version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
[ 1.266082] fuse: init (API version 7.31)
[ 1.288256] Key type asymmetric registered
[ 1.288269] Asymmetric key parser 'x509' registered
[ 1.288323] bounce: pool size: 64 pages
[ 1.288367] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[ 1.288379] io scheduler mq-deadline registered
[ 1.288388] io scheduler kyber registered
[ 1.306222] bam-dma-engine f9944000.dma-controller: WARN: Device release is not defined so it is not safe to unbind this driver while in use
[ 1.310473] msm_serial f991e000.serial: msm_serial: detected port #0
[ 1.310511] msm_serial f991e000.serial: uartclk = 7372800
[ 1.310561] f991e000.serial: ttyMSM0 at MMIO 0xf991e000 (irq = 28, base_baud = 460800) is a MSM
[ 1.310589] msm_serial: console setup on port #0
[ 1.898395] printk: console [ttyMSM0] enabled
[ 1.903559] msm_serial: driver initialized
[ 1.919151] brd: module loaded
[ 1.929372] loop: module loaded
[ 1.929912] SCSI Media Changer driver v0.25
[ 1.932366] spmi spmi-0: PMIC arbiter version v1 (0x20000002)
[ 1.949269] s1: supplied by regulator-dummy
[ 1.949606] s2: supplied by regulator-dummy
[ 1.952558] s3: supplied by regulator-dummy
[ 1.956764] s4: Bringing 5100000uV into 5000000-5000000uV
[ 1.960949] l1: supplied by regulator-dummy
[ 1.966459] l2: supplied by regulator-dummy
[ 1.970481] l3: supplied by regulator-dummy
[ 1.974614] l4: supplied by regulator-dummy
[ 1.978846] l5: supplied by regulator-dummy
[ 1.982949] l6: supplied by regulator-dummy
[ 1.987132] l7: supplied by regulator-dummy
[ 1.991315] l8: supplied by regulator-dummy
[ 1.995467] l9: supplied by regulator-dummy
[ 1.999661] l10: supplied by regulator-dummy
[ 2.003794] l11: supplied by regulator-dummy
[ 2.008334] l12: supplied by regulator-dummy
[ 2.012568] l13: supplied by regulator-dummy
[ 2.016825] l14: supplied by regulator-dummy
[ 2.021093] l15: supplied by regulator-dummy
[ 2.025335] l16: supplied by regulator-dummy
[ 2.029624] l17: supplied by regulator-dummy
[ 2.033850] l18: supplied by regulator-dummy
[ 2.038117] l19: supplied by regulator-dummy
[ 2.042351] l20: supplied by regulator-dummy
[ 2.046617] l21: supplied by regulator-dummy
[ 2.050884] l22: supplied by regulator-dummy
[ 2.055122] l23: supplied by regulator-dummy
[ 2.059395] l24: supplied by regulator-dummy
[ 2.063630] lvs1: supplied by regulator-dummy
[ 2.067841] lvs2: supplied by regulator-dummy
[ 2.072066] lvs3: supplied by regulator-dummy
[ 2.076579] 5vs1: supplied by s4
[ 2.081017] 5vs2: supplied by s4
[ 2.085591] libphy: Fixed MDIO Bus: probed
[ 2.087213] SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256) (6 bit encapsulation enabled).
[ 2.090958] CSLIP: code copyright 1989 Regents of the University of California.
[ 2.100609] usbcore: registered new interface driver ax88179_178a
[ 2.107789] usbcore: registered new interface driver cdc_ether
[ 2.114005] usbcore: registered new interface driver net1080
[ 2.119761] usbcore: registered new interface driver cdc_subset
[ 2.125572] usbcore: registered new interface driver cdc_ncm
[ 2.131410] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 2.137071] ehci-pci: EHCI PCI platform driver
[ 2.143515] usbcore: registered new interface driver cdc_acm
[ 2.147846] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[ 2.169389] rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: registered as rtc0
[ 2.169602] i2c /dev entries driver
[ 2.177084] qcom-smbb fc4cf000.spmi:pm8941@0:charger@1000: Initializing SMBB rev 3
[ 2.182317] otg-vbus: supplied by 5vs1
[ 2.187815] cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
[ 2.190071] cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
[ 2.197256] cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
[ 2.204746] cpuidle: enable-method property 'qcom,kpss-acc-v2' found operations
[ 2.212300] sdhci: Secure Digital Host Controller Interface driver
[ 2.219025] sdhci: Copyright(c) Pierre Ossman
[ 2.225230] sdhci-pltfm: SDHCI platform and OF driver helper
[ 2.230951] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 2.236664] usbcore: registered new interface driver usbhid
[ 2.240021] usbhid: USB HID core driver
[ 2.248434] oprofile: using timer interrupt.
[ 2.249403] NET: Registered protocol family 17
[ 2.253769] Key type dns_resolver registered
[ 2.258180] Registering SWP/SWPB emulation handler
[ 2.262768] Loading compiled-in X.509 certificates
[ 2.319325] debugfs: Directory 'fc4a9000.thermal-sensor' with parent 'tsens' already present!
[ 2.326483] s1: supplied by regulator-dummy
[ 2.326885] s1: Bringing 0uV into 675000-675000uV
[ 2.332731] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 2.336719] s2: supplied by regulator-dummy
[ 2.340452] s2: Bringing 0uV into 500000-500000uV
[ 2.344669] s3: supplied by regulator-dummy
[ 2.349827] ocmem fdd00000.ocmem: 8 ports, 3 regions, 2048 macros, interleaved
[ 2.353491] s3: Bringing 0uV into 500000-500000uV
[ 2.362620] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 2.365773] s4: supplied by regulator-dummy
[ 2.370062] s4: Bringing 0uV into 500000-500000uV
[ 2.374271] s5: supplied by regulator-dummy
[ 2.381554] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 2.384149] rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-07T19:24:17 UTC (3266657)
[ 2.387869] ### dt-test ### start of unittest - you will see error messages
[ 2.398101] s6: supplied by regulator-dummy
[ 2.399604] ### dt-test ### EXPECT \ : Duplicate name in testcase-data, renamed to "duplicate-name#1"
[ 2.399842] Duplicate name in testcase-data, renamed to "duplicate-name#1"
[ 2.418543] s7: supplied by regulator-dummy
[ 2.422498] ### dt-test ### EXPECT / : Duplicate name in testcase-data, renamed to "duplicate-name#1"
[ 2.423561] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 2.425369] s8: supplied by regulator-dummy
[ 2.429148] OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 2.429156] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 2.429160] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 2.439237] s1: supplied by regulator-dummy
[ 2.452933] OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 2.457091] s1: Bringing 0uV into 1300000-1300000uV
[ 2.469597] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1
[ 2.469602] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 2.484573] s2: supplied by regulator-dummy
[ 2.498542] OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 2.504829] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 2.515126] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 2.515130] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 2.515189] OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 2.520022] s2: Bringing 0uV into 2150000-2150000uV
[ 2.534335] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle
[ 2.534339] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 2.544887] s3: supplied by regulator-dummy
[ 2.548132] OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 2.555433] s3: Bringing 0uV into 1800000-1800000uV
[ 2.560266] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 2.560270] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 2.560298] OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 2.560303] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1
[ 2.560535] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
[ 2.570510] l1: supplied by s1
[ 2.579510] OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
[ 2.586682] l1: Bringing 0uV into 1225000-1225000uV
[ 2.591521] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1
[ 2.591525] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
[ 2.591587] OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
[ 2.601775] l2: supplied by s3
[ 2.611233] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle
[ 2.611268] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
[ 2.615419] l2: Bringing 0uV into 1200000-1200000uV
[ 2.623396] OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
[ 2.628271] l3: supplied by s1
[ 2.638063] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1
[ 2.640314] ### dt-test ### EXPECT \ : platform testcase-data:testcase-device2: IRQ index 0 not found
[ 2.648179] l3: Bringing 0uV into 1225000-1225000uV
[ 2.656092] platform testcase-data:testcase-device2: IRQ index 0 not found
[ 2.666227] l4: supplied by s1
[ 2.680516] ### dt-test ### EXPECT / : platform testcase-data:testcase-device2: IRQ index 0 not found
[ 2.686076] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
[ 2.696208] l4: Bringing 0uV into 1225000-1225000uV
[ 2.700903] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
[ 2.834265] l5: supplied by s2
[ 2.836015] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status
[ 2.836019] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
[ 2.847318] l5: Bringing 0uV into 1800000-1800000uV
[ 2.850356] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
[ 2.886261] l6: supplied by s2
[ 2.886399] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status
[ 2.886404] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
[ 2.898903] l6: Bringing 0uV into 1800000-1800000uV
[ 2.902539] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 2.917894] l7: supplied by s2
[ 2.932924] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
[ 2.937295] l7: Bringing 0uV into 1800000-1800000uV
[ 2.942841] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status
[ 2.942846] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
[ 2.945614] l8: supplied by regulator-dummy
[ 2.958650] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
[ 2.963000] l8: Bringing 0uV into 1800000-1800000uV
[ 2.979086] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status
[ 2.980440] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
[ 2.994350] l9: supplied by regulator-dummy
[ 2.998308] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
[ 3.011109] l9: Bringing 0uV into 1800000-1800000uV
[ 3.016696] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status
[ 3.016850] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
[ 3.031831] l10: supplied by regulator-dummy
[ 3.048351] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
[ 3.050677] l10: Bringing 0uV into 1800000-1800000uV
[ 3.064441] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status
[ 3.064446] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
[ 3.069011] l11: supplied by s1
[ 3.084690] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
[ 3.099536] l11: Bringing 0uV into 1300000-1300000uV
[ 3.104432] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 3.173762] l12: supplied by s2
[ 3.174105] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status
[ 3.174972] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
[ 3.178158] l12: Bringing 0uV into 1800000-1800000uV
[ 3.181186] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
[ 3.217801] l13: supplied by regulator-dummy
[ 3.230269] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status
[ 3.230275] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
[ 3.234444] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
[ 3.235079] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 3.249677] l13: Bringing 0uV into 1800000-1800000uV
[ 3.283658] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo
[ 3.283662] ### dt-test ### EXPECT \ : OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
[ 3.288738] ### dt-test ### EXPECT \ : OF: overlay: overlay #6 is not topmost
[ 3.304462] OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
[ 3.324871] OF: overlay: overlay #6 is not topmost
[ 3.335975] ### dt-test ### EXPECT / : OF: overlay: overlay #6 is not topmost
[ 3.335978] ### dt-test ### EXPECT / : OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8
[ 3.340707] l14: supplied by s2
[ 3.361105] l14: Bringing 0uV into 1800000-1800000uV
[ 3.364354] l15: supplied by s2
[ 3.367222] ### dt-test ### EXPECT \ : i2c i2c-1: Added multiplexed i2c bus 2
[ 3.368029] i2c i2c-1: Added multiplexed i2c bus 2
[ 3.369217] l15: Bringing 0uV into 2050000-2050000uV
[ 3.372488] ### dt-test ### EXPECT / : i2c i2c-1: Added multiplexed i2c bus 2
[ 3.372492] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
[ 3.379783] l16: supplied by regulator-dummy
[ 3.384807] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 3.389149] l16: Bringing 0uV into 2700000-2700000uV
[ 3.396589] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
[ 3.427778] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status
[ 3.427783] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
[ 3.427844] l17: supplied by regulator-dummy
[ 3.440871] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
[ 3.457520] l17: Bringing 0uV into 2700000-2700000uV
[ 3.475876] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status
[ 3.475880] ### dt-test ### EXPECT \ : i2c i2c-1: Added multiplexed i2c bus 3
[ 3.478783] l18: supplied by regulator-dummy
[ 3.497049] i2c i2c-1: Added multiplexed i2c bus 3
[ 3.497674] l18: Bringing 0uV into 2850000-2850000uV
[ 3.514706] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 3.521586] l19: supplied by regulator-dummy
[ 3.525579] ### dt-test ### EXPECT / : i2c i2c-1: Added multiplexed i2c bus 3
[ 3.534279] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-B-input) hogged as input
[ 3.535218] l19: Bringing 0uV into 3300000-3300000uV
[ 3.540558] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-A-input) hogged as input
[ 3.544881] l20: supplied by regulator-dummy
[ 3.551751] GPIO line 315 (line-B-input) hogged as input
[ 3.559114] l20: Bringing 0uV into 2950000-2950000uV
[ 3.564560] GPIO line 309 (line-A-input) hogged as input
[ 3.572690] l21: supplied by regulator-dummy
[ 3.579102] ### dt-test ### EXPECT / : GPIO line <<int>> (line-A-input) hogged as input
[ 3.581811] l21: Bringing 0uV into 2950000-2950000uV
[ 3.586628] ### dt-test ### EXPECT / : GPIO line <<int>> (line-B-input) hogged as input
[ 3.586633] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-D-input) hogged as input
[ 3.592642] l22: supplied by regulator-dummy
[ 3.600104] GPIO line 307 (line-D-input) hogged as input
[ 3.604075] l22: Bringing 0uV into 3000000-3000000uV
[ 3.609574] ### dt-test ### EXPECT / : GPIO line <<int>> (line-D-input) hogged as input
[ 3.617292] l23: supplied by regulator-dummy
[ 3.627709] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-C-input) hogged as input
[ 3.629414] l23: Bringing 0uV into 3000000-3000000uV
[ 3.635770] ### dt-test ### EXPECT / : GPIO line <<int>> (line-C-input) hogged as input
[ 3.640074] l24: supplied by regulator-dummy
[ 3.647322] mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA
[ 3.651912] l24: Bringing 0uV into 3075000-3075000uV
[ 3.659592] ### dt-test ### FAIL of_unittest_overlay_gpio():2664 unittest_gpio_chip_request() called 0 times (expected 1 time)
[ 3.665255] lvs1: supplied by s3
[ 3.682927] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
[ 3.682931] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
[ 3.684820] lvs2: supplied by s3
[ 3.690133] sdhci_msm f98a4900.sdhci: Got CD GPIO
[ 3.700948] lvs3: supplied by s3
[ 3.704316] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
[ 3.704321] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
[ 3.718126] 5vs1: supplied by s4
[ 3.731723] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
[ 3.731727] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
[ 3.734472] 5vs2: supplied by s4
[ 3.738656] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
[ 3.738660] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
[ 3.805410] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
[ 3.818689] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
[ 3.830515] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
[ 3.843341] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
[ 3.860744] mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA
[ 3.868094] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
[ 3.886817] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
[ 3.897848] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
[ 3.910448] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
[ 3.923033] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
[ 3.934061] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
[ 3.945320] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
[ 3.956218] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
[ 3.965748] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
[ 3.975753] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
[ 3.991170] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right
[ 3.991174] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left
[ 3.996032] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200
[ 4.008806] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2
[ 4.009664] msm_hsusb f9a55000.usb: failed to create device link to ci_hdrc.0.ulpi
[ 4.021413] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate
[ 4.021416] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color
[ 4.052920] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status
[ 4.066380] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up
[ 4.079700] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up
[ 4.093071] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status
[ 4.108241] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status
[ 4.123325] ### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
[ 4.136370] ### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
[ 4.150628] OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
[ 4.179147] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
[ 4.190137] ### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name
[ 4.190145] ### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller
[ 4.202662] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.217880] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.231256] ### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.231507] mmc1: new ultra high speed DDR50 SDHC card at address aaaa
[ 4.246031] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.271061] mmcblk1: mmc1:aaaa SU16G 14.8 GiB
[ 4.275021] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.298499] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.298507] mmcblk1: p1
[ 4.310625] ### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.310629] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.325399] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail
[ 4.340232] ### dt-test ### end of unittest - 258 passed, 1 failed
[ 4.369695] ALSA device list:
[ 4.375127] No soundc�[ 4.382470] Freeing unused kernel memory: 1024K
[ 4.392204] mmcblk0: mmc0:0001 SEM16G 14.7 GiB
[ 4.392431] mmcblk0boot0: mmc0:0001 SEM16G partition 1 4.00 MiB
[ 4.395717] mmcblk0boot1: mmc0:0001 SEM16G partition 2 4.00 MiB
[ 4.401692] mmcblk0rpmb: mmc0:0001 SEM16G partition 3 4.00 MiB, chardev (247:0)
[ 4.407818] Run /init as init process
[ 4.416285] mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20
mkdir: can't create directory '/bin': File exists
mkdir: can't create directory '/dev': File exists
/init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory
mdev: unknown user/group 'root:uucp' on line 34
Attempt to mount partitions: /usr/system /usr/data
Mounting partitions from: /dev/mmcblk0
[ 4.912251] EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Opts: (null)
[ 4.932285] EXT4-fs (mmcblk0p13): recovery complete
[ 4.932321] EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Opts: (null)
/ # [ 5.288283] random: fast init done

/ # cat /proc/version
Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020

2022-02-28 20:27:11

by Frank Rowand

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

Hi Rob,

Ping.

-Frank

On 2/1/22 12:14, [email protected] wrote:
> From: Frank Rowand <[email protected]>
>
> 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 <[email protected]>
> ---
> permissions for scripts/dtc/of_unittest should be 770
>
> I will reply to this message with the usage message from
> 'scripts/dtc/of_unittest_expect --help'.
>
> I will also reply with examples of raw and processed console logs.
>
> 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(/<</, $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";
> + }
> +}

2022-02-28 21:30:02

by Rob Herring

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

On Tue, Feb 1, 2022 at 12:14 PM <[email protected]> wrote:
>
> From: Frank Rowand <[email protected]>
>
> 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 <[email protected]>
> ---
> permissions for scripts/dtc/of_unittest should be 770

Why? 755 is what the patch says and what most/all executables in the kernel are.

Rob

>
> I will reply to this message with the usage message from
> 'scripts/dtc/of_unittest_expect --help'.
>
> I will also reply with examples of raw and processed console logs.
>
> 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

2022-03-01 04:58:01

by Frank Rowand

[permalink] [raw]
Subject: Re: [PATCH 1/1] of: unittest: add program to process EXPECT messages

On 2/28/22 15:24, Rob Herring wrote:
> On Tue, Feb 1, 2022 at 12:14 PM <[email protected]> wrote:
>>
>> From: Frank Rowand <[email protected]>
>>
>> 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 <[email protected]>
>> ---
>> permissions for scripts/dtc/of_unittest should be 770
>
> Why? 755 is what the patch says and what most/all executables in the kernel are.

I based that on the permissions of other executables in scripts/dtc/

I do like 755 better, thanks for pointing out the wider population of
executables in the kernel.

-Frank

>
> Rob
>
>>
>> I will reply to this message with the usage message from
>> 'scripts/dtc/of_unittest_expect --help'.
>>
>> I will also reply with examples of raw and processed console logs.
>>
>> 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