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>
 <5c0c1ad7-c3c6-39b9-0907-330241d40464@gmail.com>
Message-ID: <9aa2b75a-d848-5a87-2e2b-07f2931bd031@gmail.com>
Date:   Tue, 23 Jun 2020 19:15:20 -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: <5c0c1ad7-c3c6-39b9-0907-330241d40464@gmail.com>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On 2020-06-21 17:49, Frank Rowand wrote:
> 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 1/5
> 
> expected messages API:
> 
>   - execute EXPECT_BEGIN(), reporting the expected message, before the
>     point when the message will occur
> 
>   - execute EXPECT_END(), reporting the same expected message, after the
>     point when the message will occur
> 
>   - EXPECT_BEGIN() may occur multiple times, before the corresponding
>     EXPECT_END()s, when a single test action may result in multiple
>     expected messages
> 
>   - When multiple EXPECT_BEGIN()s are nested, the corresponding (matching)
>     EXPECT_END()s occur in the inverse order of the EXPECT_BEGIN()s.
> 
>   - When the expected message contain a non-constant value, a place holder
>     can be placed in the message.  Current place holders are:
> 
>      - <<int>>  an integer
>      - <<hex>>  a hexadecimal number
> 
>      Suggested additional place holder(s) are:
> 
>        - <<alpha>>  contiguous non white space characters 
> 
>        I have avoided allowing regular expessions, because test frameworks
>        may implement their own filtering instead of relying on a generic
>        console output filter program.  There are multiple definitions for
>        regular expressions in different languages, thus it could be
>        difficult to set rules for a subset of regular expression usable
>        by all languages.
> 
> A preliminary version of an expected messages framework has been
> implemented in the mainline drivers/of/unittest.c.  The implementation
> is trivial, as seen below.
> 
> Note that the define of "pr_fmt()" pre-dates the implementation
> of the EXPECT_BEGIN() and EXPECT_END() macros.
> ---------------------------------------------------------------
> 
> #define pr_fmt(fmt) "### dt-test ### " fmt
> 
> 
> /*
>  * Expected message may have a message level other than KERN_INFO.
>  * Print the expected message only if the current loglevel will allow
>  * the actual message to print.
>  *
>  * Do not use EXPECT_BEGIN() or EXPECT_END() for messages generated by
>  * pr_debug().
>  */
> #define EXPECT_BEGIN(level, fmt, ...) \
>         printk(level pr_fmt("EXPECT \\ : ") fmt, ##__VA_ARGS__)
> 
> #define EXPECT_END(level, fmt, ...) \
>         printk(level pr_fmt("EXPECT / : ") fmt, ##__VA_ARGS__)
> 
> 
> 
> Example 1 of the API use, single message:
> -----------------------------------------
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> 
>         rc = of_parse_phandle_with_args(np, "phandle-list-bad-phandle",
>                                         "#phandle-cells", 0, &args);
> 
>         EXPECT_END(KERN_INFO,
>                    "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> 
> 
> Example 2 of the API use, two messages,
> "<<int>>" placeholder matches any integer:
> ------------------------------------------
> 
>         /*
>          * messages are the result of the probes, after the
>          * driver is registered
>          */
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "GPIO line <<int>> (line-B-input) hogged as input\n");
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "GPIO line <<int>> (line-A-input) hogged as input\n");
> 
>         ret = platform_driver_register(&unittest_gpio_driver);
>         if (unittest(ret == 0, "could not register unittest gpio driver\n"))
>                 return;
> 
>         EXPECT_END(KERN_INFO,
>                    "GPIO line <<int>> (line-A-input) hogged as input\n");
>         EXPECT_END(KERN_INFO,
>                    "GPIO line <<int>> (line-B-input) hogged as input\n");
> 
> Subtle flow of control issue: the two EXPECT_END() are not executed if
> platform_driver_register() fails.  The two expected messages will not
> be printed, but the filter tool (of_unittest_expect) will not report this
> as an error because of_unittest_expect does not search for the messages
> until the EXPEND_END() output is encountered.
> 
> One could argue that this is correct behavior because unittest() will print
> the error that platform_driver_register() failed.  The "expected" messages
> are not expected if the register fails.
> 
> One could equally well argue that the two EXPECT_END() should execute
> before unittest() checks the value of ret, so the missing messages will
> be reported as an error by of_unittest_expect.
> 
> But that is a discussion that should occur in the context of whether
> drivers/of/unittest.c has a coding error, not in the context of how
> to implement the expected messages framework.
> 
> 
> goals:
> 
>   - The console output should be human readable and easy to parse.
>     Have "\" in the expect begin and a matching "/" in the expect end
>     is intended to make it easier to visualize pairs.
> 
>   - The console output should be machine parsable.
> 
> 
> Design alternate choices:
> 
>   - Expect message nesting:
>      1) Nested expect messages place the "\" in the same column.
>      2) For each nested expect message, indent the "\" by one more column
>         for each level of nesting.
> 
>     Chose 1.  This keeps the EXPECT_BEGIN() and EXPECT_END() macros very
>     simple, at the expense of the output being less human readable in the
>     raw log.
> 
>     The raw log is already not very readable, and I would expect the normal
>     use case would be using a filter program, such as of_unittest_expect,
>     to handle the readability issue.
> 
> 
> Issues:
> 
>   - The EXPECT_BEGIN() and EXPECT_END() macros use printk() for output.
>     printk() prefixes the output with the value of the pr_fmt() macro.
>     This means the filter program must be able to deal with different
>     pr_fmt() strings being incorporated in the expect messages that
>     are in different source files.  The unittest.c pr_fmt() value is
>     currently hard coded in the of_unittest_expect filter program.
> 
>   - The output of the of_unittest_expect filter program prepends several
>     columns of data at the beginning of the resulting filtered data.  The
>     TAP format does not expect these extra columns.
> 
>     The prepended data is very important for making the report easily
>     read by humans.
> 
>     1) It will be trivial to add an of_unittest_expect "--tap-out" option
>        to not add the prepended data, so that normal TAP programs can use
>        the output from of_unittest_expect.
> 
>     2) The "--tap-out" option could also create a TAP "test line" reporting
>        an "ok" for expected message detected and "not ok" if an expected
>        message is not detected.
> 
>        This would also require modifying the "test plan" line to change
>        the number of tests.
> 
  - KUnit already has a concept that uses the word "expect".  A test may
    have expectations about what the data created or modified by the test
    will be.  For example, if the test invokes:

       ret = add(3, 4)

    then the test might expect ret to contain the value "7".  If it does
    not, then the test could report:

       ret = add(14, -7)
       expected ret == 7, but instead ret == -22

    (Don't take this example as a valid KUnit format, I just trying to
    explain the concept.)

    The word EXPECT in this new feature should be changed to something else
    to avoid confusion with the other KUnit concept.  Or alternately,
    KUnit could change the word used for its existing concept, if that
    is an easier change.