Re: RFC: KTAP documentation - expected messages
On Tue, 23 Jun 2020, David Gow wrote: > On Mon, Jun 22, 2020 at 6:45 AM 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. > > Thanks for doing this: I think there are quite a few tests which could > benefit from something like this. > > I think there were actually two separate questions: what do we do with > unexpected messages (most of which I expect are useless, but some of > which may end up being related to an unexpected test failure), and how > to have tests "expect" a particular message to appear. I'll stick to > talking about the latter for this thread, but even there there's two > possible interpretations of "expected messages" we probably want to > explicitly distinguish between: a message which must be present for > the test to pass (which I think best fits the "expected message" > name), and a message which the test is likely to produce, but which > shouldn't alter the result (an "ignored message"). I don't see much > use for the latter at present, but if we wanted to do more things with > messages and had some otherwise very verbose tests, it could > potentially be useful. > > The other thing I'd note here is that this proposal seems to be doing > all of the actual message filtering in userspace, which makes a lot of > sense for kselftest tests, but does mean that the kernel can't know if > the test has passed or failed. There's definitely a tradeoff between > trying to put too much needless string parsing in the kernel and > having to have a userland tool determine the test results. The > proposed KCSAN test suite[1] is using tracepoints to do this in the > kernel. It's not the cleanest thing, but there's no reason KUnit or > similar couldn't implement a nicer API around it. > > [1]: https://lkml.org/lkml/2020/6/22/1506 > For KTF the way we handled this was to use the APIs for catching function entry and return (via kprobes), specifying printk as the function to catch, and checking its argument string to verify the expected message was seen. That allows you to verify that messages appear in kernel testing context, but it's not ideal as printk() has not yet filled in the arguments in the buffer for display (there may be a better place to trace). If it seems like it could be useful I could have a go at porting the kprobe stuff to KUnit, as it helps expand the vocabulary for what can be tested in kernel context; for example we can also override return values for kernel functions to simulate errors. Alan
RE: RFC: KTAP documentation - expected messages
> -Original Message-
> From: Frank Rowand
>
> 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:
> >
> > - <> an integer
> > - <> a hexadecimal number
> >
> > Suggested additional place holder(s) are:
> >
> >- <> 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",
> >
Re: RFC: KTAP documentation - expected messages
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:
>
> - <> an integer
> - <> a hexadecimal number
>
> Suggested additional place holder(s) are:
>
>- <> 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, );
>
> EXPECT_END(KERN_INFO,
>"OF: /testcase-data/phandle-tests/consumer-a: could not
> find phandle");
>
>
> Example 2 of the API use, two messages,
> "<>" placeholder matches any integer:
>
Re: RFC: KTAP documentation - expected messages
+Dmitry, since Brendan added him to another reply at this thread level On 2020-06-22 21:46, David Gow wrote: > On Mon, Jun 22, 2020 at 6:45 AM 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. > > Thanks for doing this: I think there are quite a few tests which could > benefit from something like this. > > I think there were actually two separate questions: what do we do with > unexpected messages (most of which I expect are useless, but some of > which may end up being related to an unexpected test failure), and how > to have tests "expect" a particular message to appear. I'll stick to Yes. But there is also a third aspect that made this feature important for the Devicetree unittest. There was a question on the devicetree mail list, asking whether some devicetree related kernel warning and/or error messages were devicetree problems. The messages appeared while the unittest was executing, but at the same time a lot of system initialization is in progress, resulting in lots of console messages that are unrelated to unittest. I could not in good conscious reply that the messages were truly of no consequence without actually chasing each of them down and verifying that they were triggered by unittest, and were showing what the devicetree infrastructure should be reporting in response to the test stimulus, vs an underlying bug in the devicetree infrastructure. I found the expected messages API to be a useful tool to document the validity of the messages, both for myself, and for the random developer who might be reading the boot messages. > talking about the latter for this thread, but even there there's two > possible interpretations of "expected messages" we probably want to > explicitly distinguish between: a message which must be present for > the test to pass (which I think best fits the "expected message" > name), and a message which the test is likely to produce, but which > shouldn't alter the result (an "ignored message"). This type of case was the impetus for me to create the API. There was a unittest that resulted in the probe of a device, where the probe executed devicetree subsystem code that invoked a blocking_notifier_call_chain(), that resulted in another subsystem taking some action, and that action just happened to do a printk() reporting a specific action that the unittest was trying to verify. I was able to verify much of the asynchronous activity by creating a fake driver and corresponding devices to be probed and could instrument the fake driver. The printk() information provided the last little bit of checking for correct behavior. > I don't see much > use for the latter at present, but if we wanted to do more things with > messages and had some otherwise very verbose tests, it could > potentially be useful. The use for the "ignored message" is my third aspect above. This points out that yet another possible consumer of the console boot log is the QA or test engineer. They can have the same concerns as any "random developer". > > The other thing I'd note here is that this proposal seems to be doing > all of the actual message filtering in userspace, which makes a lot of > sense for kselftest tests, but does mean that the kernel can't know if > the test has passed or failed. Yes. I had absolutely no interest in my test code examining the history of console messages, which could be generated on any other processor. The printk related code has always been complex, nuanced, and seems to attract the attention of people who want to change it instead of leaving it stable. I would really like to stay away from any dependency on it. > There's definitely a tradeoff between > trying to put too much needless string parsing in the kernel and > having to have a userland tool determine the test results. The > proposed KCSAN test suite[1] is using tracepoints to do this in the > kernel. It's not the cleanest thing, but there's no reason KUnit or > similar couldn't implement a nicer API around it. My interest is in printk() based messages that are present in areas outside of my test code and independent of my test code. I specifically did not want to modify that existing code with any test code. I was willing to accept the extra layer of running a user space program to process the console output to verify one small portion of the test passing or failing (or alternately, just examining the console
Re: RFC: KTAP documentation - expected messages
On Mon, Jun 22, 2020 at 7:47 PM David Gow wrote: > > On Mon, Jun 22, 2020 at 6:45 AM 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. > > Thanks for doing this: I think there are quite a few tests which could > benefit from something like this. > > I think there were actually two separate questions: what do we do with > unexpected messages (most of which I expect are useless, but some of > which may end up being related to an unexpected test failure), and how > to have tests "expect" a particular message to appear. I'll stick to > talking about the latter for this thread, but even there there's two > possible interpretations of "expected messages" we probably want to > explicitly distinguish between: a message which must be present for > the test to pass (which I think best fits the "expected message" > name), and a message which the test is likely to produce, but which > shouldn't alter the result (an "ignored message"). I don't see much > use for the latter at present, but if we wanted to do more things with > messages and had some otherwise very verbose tests, it could > potentially be useful. +Dmitry Vyukov, I think you were interested in this for KASAN before we went with the signalling approach. Any thoughts? > The other thing I'd note here is that this proposal seems to be doing > all of the actual message filtering in userspace, which makes a lot of > sense for kselftest tests, but does mean that the kernel can't know if > the test has passed or failed. There's definitely a tradeoff between > trying to put too much needless string parsing in the kernel and > having to have a userland tool determine the test results. The > proposed KCSAN test suite[1] is using tracepoints to do this in the > kernel. It's not the cleanest thing, but there's no reason KUnit or > similar couldn't implement a nicer API around it. > > [1]: https://lkml.org/lkml/2020/6/22/1506 > > > 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. > > Is having a nice way to handle expected messages the only thing > holding up porting this to KUnit? > > > 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. > > Cheers, > -- David
Re: RFC: KTAP documentation - expected messages
On Mon, Jun 22, 2020 at 6:45 AM 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. Thanks for doing this: I think there are quite a few tests which could benefit from something like this. I think there were actually two separate questions: what do we do with unexpected messages (most of which I expect are useless, but some of which may end up being related to an unexpected test failure), and how to have tests "expect" a particular message to appear. I'll stick to talking about the latter for this thread, but even there there's two possible interpretations of "expected messages" we probably want to explicitly distinguish between: a message which must be present for the test to pass (which I think best fits the "expected message" name), and a message which the test is likely to produce, but which shouldn't alter the result (an "ignored message"). I don't see much use for the latter at present, but if we wanted to do more things with messages and had some otherwise very verbose tests, it could potentially be useful. The other thing I'd note here is that this proposal seems to be doing all of the actual message filtering in userspace, which makes a lot of sense for kselftest tests, but does mean that the kernel can't know if the test has passed or failed. There's definitely a tradeoff between trying to put too much needless string parsing in the kernel and having to have a userland tool determine the test results. The proposed KCSAN test suite[1] is using tracepoints to do this in the kernel. It's not the cleanest thing, but there's no reason KUnit or similar couldn't implement a nicer API around it. [1]: https://lkml.org/lkml/2020/6/22/1506 > 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. Is having a nice way to handle expected messages the only thing holding up porting this to KUnit? > 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. Cheers, -- David
Re: RFC: KTAP documentation - expected messages
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:
>
> - <> an integer
> - <> a hexadecimal number
>
> Suggested additional place holder(s) are:
>
>- <> 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:
> -
>
>
Re: RFC: KTAP documentation - expected messages
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 5/5 This is the previous raw console output for the Devicetree unittest, filtered by of_unittest_expect. The expected messages are eliminated instead of being flagged. Lines 1 - 205 deleted again. The output is still somewhat noisy because the Devicetree unittest is running in parallel with some unrelated driver initialization. This test run shows one of the unittests failing (search for the string "FAIL") and an associated expected console error message is missing. EXPECT begin and EXPECT end lines are suppressed. Lines that match an EXPECT line are suppressed. Lines reporting a of_unittest_expect warning or error are flagged with a leading '**'. Lines reporting start or end of the unittests are flagged with a leading '->'. Lines reporting a unittest test FAIL are flagged with a leading '>>'. s4: supplied by regulator-dummy s4: Bringing 0uV into 50-50uV s5: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-07T19:24:17 UTC (3266657) -> ### dt-test ### start of unittest - you will see error messages s6: supplied by regulator-dummy s7: supplied by regulator-dummy s8: supplied by regulator-dummy s1: supplied by regulator-dummy s1: Bringing 0uV into 130-130uV s2: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO s2: Bringing 0uV into 215-215uV s3: supplied by regulator-dummy s3: Bringing 0uV into 180-180uV l1: supplied by s1 l1: Bringing 0uV into 1225000-1225000uV l2: supplied by s3 l2: Bringing 0uV into 120-120uV l3: supplied by s1 l3: Bringing 0uV into 1225000-1225000uV l4: supplied by s1 l4: Bringing 0uV into 1225000-1225000uV l5: supplied by s2 l5: Bringing 0uV into 180-180uV l6: supplied by s2 l6: Bringing 0uV into 180-180uV sdhci_msm f98a4900.sdhci: Got CD GPIO l7: supplied by s2 l7: Bringing 0uV into 180-180uV l8: supplied by regulator-dummy l8: Bringing 0uV into 180-180uV l9: supplied by regulator-dummy l9: Bringing 0uV into 180-180uV l10: supplied by regulator-dummy l10: Bringing 0uV into 180-180uV l11: supplied by s1 l11: Bringing 0uV into 130-130uV sdhci_msm f98a4900.sdhci: Got CD GPIO l12: supplied by s2 l12: Bringing 0uV into 180-180uV l13: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO l13: Bringing 0uV into 180-180uV l14: supplied by s2 l14: Bringing 0uV into 180-180uV l15: supplied by s2 l15: Bringing 0uV into 205-205uV l16: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO l16: Bringing 0uV into 270-270uV l17: supplied by regulator-dummy l17: Bringing 0uV
Re: RFC: KTAP documentation - expected messages
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 4/5 This is the previous raw console output for the Devicetree unittest, filtered by of_unittest_expect. The expected messages are not eliminated, but are flagged with "ok" in the leading columns. Lines 1 - 205 deleted again. This test run shows one of the unittests failing (search for the string "FAIL") and an associated expected console error message is missing. EXPECT begin and EXPECT end lines are suppressed. Lines that match an EXPECT line are flagged with a leading 'ok'. Lines reporting a of_unittest_expect warning or error are flagged with a leading '**'. Lines reporting start or end of the unittests are flagged with a leading '->'. Lines reporting a unittest test FAIL are flagged with a leading '>>'. s4: Bringing 0uV into 50-50uV s5: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-07T19:24:17 UTC (3266657) -> ### dt-test ### start of unittest - you will see error messages s6: supplied by regulator-dummy ok Duplicate name in testcase-data, renamed to "duplicate-name#1" s7: supplied by regulator-dummy s8: supplied by regulator-dummy ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 s1: supplied by regulator-dummy ok OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 s1: Bringing 0uV into 130-130uV s2: supplied by regulator-dummy ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle sdhci_msm f98a4900.sdhci: Got CD GPIO ok OF: /testcase-data/phandle-tests/consumer-a: could not find phandle s2: Bringing 0uV into 215-215uV s3: supplied by regulator-dummy ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 s3: Bringing 0uV into 180-180uV ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 l1: supplied by s1 ok OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1 l1: Bringing 0uV into 1225000-1225000uV ok OF: /testcase-data/phandle-tests/consumer-b: could not find phandle l2: supplied by s3 l2: Bringing 0uV into 120-120uV ok OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1 l3: supplied by s1 l3: Bringing 0uV into 1225000-1225000uV ok platform testcase-data:testcase-device2: IRQ index 0 not found l4: supplied by s1 l4: Bringing 0uV into 1225000-1225000uV ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status l5: supplied by s2 l5: Bringing 0uV into 180-180uV ok OF: overlay: WARNING: memory leak will
Re: RFC: KTAP documentation - expected messages
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 3/5 This is the raw console output for the Devicetree unittest. Even with lines 1 - 205 deleted, this is pretty noisy and difficult to read. This test run shows one of the unittests failing (search for the string "FAIL") and an associated expected console error message is missing. [2.370062] s4: Bringing 0uV into 50-50uV [2.374271] s5: supplied by regulator-dummy [2.381554] sdhci_msm f98a4900.sdhci: Got CD GPIO [2.384149] rtc-pm8xxx fc4cf000.spmi:pm8941@0:rtc@6000: setting system clock to 1970-02-07T19:24:17 UTC (3266657) [2.387869] ### dt-test ### start of unittest - you will see error messages [2.398101] s6: supplied by regulator-dummy [2.399604] ### dt-test ### EXPECT \ : Duplicate name in testcase-data, renamed to "duplicate-name#1" [2.399842] Duplicate name in testcase-data, renamed to "duplicate-name#1" [2.418543] s7: supplied by regulator-dummy [2.422498] ### dt-test ### EXPECT / : Duplicate name in testcase-data, renamed to "duplicate-name#1" [2.423561] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 [2.425369] s8: supplied by regulator-dummy [2.429148] OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 [2.429156] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 [2.429160] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 [2.439237] s1: supplied by regulator-dummy [2.452933] OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 [2.457091] s1: Bringing 0uV into 130-130uV [2.469597] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not get #phandle-cells-missing for /testcase-data/phandle-tests/provider1 [2.469602] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle [2.484573] s2: supplied by regulator-dummy [2.498542] OF: /testcase-data/phandle-tests/consumer-a: could not find phandle [2.504829] sdhci_msm f98a4900.sdhci: Got CD GPIO [2.515126] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle [2.515130] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle [2.515189] OF: /testcase-data/phandle-tests/consumer-a: could not find phandle [2.520022] s2: Bringing 0uV into 215-215uV [2.534335] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find
Re: RFC: KTAP documentation - expected messages
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 2/5
#!/usr/bin/perl
# SPDX-License-Identifier: GPL-2.0
#
# Copyright 2020 Sony Corporation
#
# Author: Frank Rowand
# This program is meant to be an aid to reading the output of the Linux
# kernel devicetree unittest (drivers/of/unitest.c). A design goal of
# unittest is that the output is directly usable without a helper program
# such as this one.
$VUFX = "200115a";
use strict 'refs';
use strict subs;
use Getopt::Long;
use Text::Wrap;
# strip off everything before final "/"
(undef, $script_name) = split(/^.*\//, $0);
#__
sub compare {
my ($expect, $got) = @_;
my $expect_next;
my $expect_next_lit;
my $got_next;
my $type;
while ($expect) {
($expect_next, $type) = split(/<>/, $type);
$expect =~ s/^.*?>>//; # '?' is non-greedy, minimal match
# literal, ignore all metacharacters when used in a regex
$expect_next_lit = quotemeta($expect_next);
$got_next = $got;
$got_next =~ s/^($expect_next_lit).*/\1/;
$got =~ s/^$expect_next_lit//;
if ($expect_next ne $got_next) {
return 0;
}
if ($type eq "int") {
if ($got =~ /^[+-]*[0-9]+/) {
$got =~ s/^[+-]*[0-9]+//;
} else {
return 0;
}
} elsif ($type eq "hex") {
if ($got =~ /^(0x)*[0-9a-f]+/) {
$got =~ s/^(0x)*[0-9a-f]+//;
} else {
return 0;
}
} elsif ($type eq "") {
if ($expect_next ne $got_next) {
return 0;
} else {
return 1;
}
} else {
print "ERROR: type not recognized: $type\n";
return 0;
}
}
# should not get here
print "ERROR: $script_name internal error, at end of compare()\n";
return 0;
}
#__
sub usage {
# * when editing, be careful to not put tabs in the string printed:
print STDERR
"
usage:
$script_name CONSOLE_LOG
-hprint program usage
--help print program usage
--hide-expect suppress output of EXPECTed lines
--line-num report line number of CONSOLE_LOG
--no-strip-ts do not strip leading timestamp
--version print program version and exit
Re: RFC: KTAP documentation - expected messages
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:
- <> an integer
- <> a hexadecimal number
Suggested additional place holder(s) are:
- <> 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, );
EXPECT_END(KERN_INFO,
"OF: /testcase-data/phandle-tests/consumer-a: could not find
phandle");
Example 2 of the API use, two messages,
"<>" placeholder matches any integer:
--
/*
* messages are the result of the probes, after the
* driver is registered
*/
EXPECT_BEGIN(KERN_INFO,
"GPIO line <>
RFC: KTAP documentation - expected messages
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.
