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

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

reply 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
   / #