Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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@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 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__)

I included the pr_fmt() in EXPECT_BEGIN() and EXPECT_END(), because I
defined the two macros within the unittest.c file.

For a KTAP compliant generic implementation, I would change these
to be diagnostic messages, so:

  #define EXPECT_BEGIN(level, fmt, ...) \
          printk(level "# EXPECT \\ : " fmt, ##__VA_ARGS__)
  
  #define EXPECT_END(level, fmt, ...) \
          printk(level "# EXPECT / : " fmt, ##__VA_ARGS__)

This also fixes the first issue in the "Issues" list below.

-Frank

> 
> 
> 
> 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.
>