Re: RFC: KTAP documentation - expected messages

From: Frank Rowand
Date: Sun Jun 21 2020 - 18:52:39 EST


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

reply 5/5

This is the previous raw console output for the Devicetree unittest,
filtered by of_unittest_expect. The expected messages are eliminated
instead of being flagged.

Lines 1 - 205 deleted again.

The output is still somewhat noisy because the Devicetree unittest
is running in parallel with some unrelated driver initialization.

This test run shows one of the unittests failing (search for
the string "FAIL") and an associated expected console error
message is missing.

EXPECT begin and EXPECT end lines are suppressed.
Lines that match an EXPECT line are suppressed.
Lines reporting a of_unittest_expect warning or error are flagged
with a leading '**'.
Lines reporting start or end of the unittests are flagged
with a leading '->'.
Lines reporting a unittest test FAIL are flagged
with a leading '>>'.


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
s7: supplied by regulator-dummy
s8: supplied by regulator-dummy
s1: supplied by regulator-dummy
s1: Bringing 0uV into 1300000-1300000uV
s2: supplied by regulator-dummy
sdhci_msm f98a4900.sdhci: Got CD GPIO
s2: Bringing 0uV into 2150000-2150000uV
s3: supplied by regulator-dummy
s3: Bringing 0uV into 1800000-1800000uV
l1: supplied by s1
l1: Bringing 0uV into 1225000-1225000uV
l2: supplied by s3
l2: Bringing 0uV into 1200000-1200000uV
l3: supplied by s1
l3: Bringing 0uV into 1225000-1225000uV
l4: supplied by s1
l4: Bringing 0uV into 1225000-1225000uV
l5: supplied by s2
l5: Bringing 0uV into 1800000-1800000uV
l6: supplied by s2
l6: Bringing 0uV into 1800000-1800000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l7: supplied by s2
l7: Bringing 0uV into 1800000-1800000uV
l8: supplied by regulator-dummy
l8: Bringing 0uV into 1800000-1800000uV
l9: supplied by regulator-dummy
l9: Bringing 0uV into 1800000-1800000uV
l10: supplied by regulator-dummy
l10: Bringing 0uV into 1800000-1800000uV
l11: supplied by s1
l11: Bringing 0uV into 1300000-1300000uV
sdhci_msm f98a4900.sdhci: Got CD GPIO
l12: supplied by s2
l12: Bringing 0uV into 1800000-1800000uV
l13: supplied by regulator-dummy
sdhci_msm f98a4900.sdhci: Got CD GPIO
l13: Bringing 0uV into 1800000-1800000uV
l14: supplied by s2
l14: Bringing 0uV into 1800000-1800000uV
l15: supplied by s2
l15: Bringing 0uV into 2050000-2050000uV
l16: supplied by regulator-dummy
sdhci_msm f98a4900.sdhci: Got CD GPIO
l16: Bringing 0uV into 2700000-2700000uV
l17: supplied by regulator-dummy
l17: Bringing 0uV into 2700000-2700000uV
l18: supplied by regulator-dummy
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
l20: Bringing 0uV into 2950000-2950000uV
l21: supplied by regulator-dummy
l21: Bringing 0uV into 2950000-2950000uV
l22: supplied by regulator-dummy
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
mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA
msm_hsusb f9a55000.usb: failed to create device link to ci_hdrc.0.ulpi
mmc1: new ultra high speed DDR50 SDHC card at address aaaa
mmcblk1: mmc1:aaaa SU16G 14.8 GiB
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
/ #