Message-ID: <CY4PR13MB1175B3A4C3EB2A79185632F8FD950@CY4PR13MB1175.namprd13.prod.outlook.com>
Date:   Wed, 24 Jun 2020 00:22:43 +0000
From:   "Bird, Tim" <Tim.Bird@...y.com>
To:     Frank Rowand <frowand.list@...il.com>,
        "shuah@...nel.org" <shuah@...nel.org>,
        "linux-kselftest@...r.kernel.org" <linux-kselftest@...r.kernel.org>,
        Brendan Higgins <brendanhiggins@...gle.com>,
        David Gow <davidgow@...gle.com>,
        Kees Cook <keescook@...omium.org>,
        Paolo Bonzini <pbonzini@...hat.com>
CC:     "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
Subject: RE: RFC: KTAP documentation - expected messages



> -----Original Message-----
> From: Frank Rowand <frowand.list@...il.com>
> 
> 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.
> 
A lot of test systems use "expected value" or terminology to that effect,
and compare that with "value seen" or "value received".  I didn't follow
this thread closely.  Does the test scan the logs looking for specific messages
to match against, to determine pass/fail criteria?  If so, then EXPECT
is OK in this context.  If it is being done afterwards by a human, then 
I think the marker should be called something else.
 -- Tim

Powered by blists - more mailing lists