Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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



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.