> -----Original Message-----
> From: Frank Rowand <frowand.l...@gmail.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/cy4pr13mb1175b804e31e502221bc8163fd...@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