> -----Original Message----- > From: Frank Rowand <frowand.list@xxxxxxxxx> > > 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__) > > > > > > > > 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
