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