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@CY4PR13MB11...
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.
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@CY4PR13MB11...
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.gitAn 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.
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@CY4PR13MB11...
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.gitAn 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:
- Nested expect messages place the "" in the same column.
- 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.
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.
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.
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@CY4PR13MB11...
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.gitAn 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:
- Nested expect messages place the "" in the same column.
- 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.
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.
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.
-----Original Message----- From: Frank Rowand frowand.list@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/CY4PR13MB1175B804E31E502221BC8163FD830@CY4PR13MB11...
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.gitAn 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:
- Nested expect messages place the "" in the same column.
- 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.
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.
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
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@CY4PR13MB11...
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.gitAn 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(/<</, $expect); ($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
-h print 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
Process a console log for EXPECTed test related messages to either highlight expected devicetree unittest related messages or suppress the messages.
Various unittests may trigger kernel messages from outside the unittest code. The unittest annotates any such message with an EXPECT begin before triggering the message, and an EXPECT end after triggering the message.
If an expected message does not occur, that will be reported.
If EXPECT begin and EXPECT end lines do not match, that will be reported. If nested, EXPECT end lines must be in the reverse order of the corresponding EXPECT begin lines.
EXPECT begin and EXPECT end lines can contain special patterns:
<<int>> matches: [+-]*[0-9]+ <<hex>> matches: (0x)*[0-9a-f]+
Default: - strip timestamps
EXPECT begin and EXPECT end lines are suppressed. Lines that match an EXPECT line are flagged with a leading 'ok'. Lines reporting a $script_name 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 '>>'.
";
return {}; }
#______________________________________________________________________________ #______________________________________________________________________________
# save for usage()
if (!GetOptions( "h" => $help, "help" => $help, "hide-expect" => $hide_expect, "line-num" => $print_line_num, "no-strip-ts" => $no_strip_ts, "verbose" => $verbose, "version" => $version, )) { print STDERR "\n"; print STDERR "ERROR processing command line options\n"; print STDERR "\n"; print STDERR "For help, type '$script_name --help'\n"; print STDERR "\n";
exit 1; }
if ($no_strip_ts) { $strip_ts = 1; $no_strip_ts = 0; } else { $strip_ts = 0; $no_strip_ts = 1; }
# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - if ($help){
&usage;
exit 1; }
# - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
if ($version) { print STDERR "\n$script_name $VUFX\n\n"; print STDERR "\n";
exit 0; }
#______________________________________________________________________________
# $debug = 1;
# zzz: #if ($#ARGV != 1) { # print STDERR "\n"; # print STDERR "Required arguments: two file names\n"; # print STDERR "\n"; # # exit 0; #}
# $exp_* are used as regex match patterns, # so '\\' in $exp_begin matches a single '' # quotemeta() does not do the right thing in this case
$pr_fmt = "### dt-test ### "; $exp_begin = "${pr_fmt}EXPECT \\ : "; $exp_end = "${pr_fmt}EXPECT / : ";
$line_num = ""; $timestamp = "";
LINE: while ($line = <ARGV>) {
chomp $line;
$prefix = " "; ## 2 characters
if ($strip_ts) {
$timestamp = $line;
if ($timestamp =~ /^[\s*[0-9]+.[0-9]*] /) { ($timestamp, $null) = split(/]/, $line); $timestamp = $timestamp . "] ";
} else { $timestamp = ""; } }
$line =~ s/^[\s*[0-9]+.[0-9]*] //;
# ----- find EXPECT begin
if ($line =~ /^\s*$exp_begin/) { $data = $line; $data =~ s/^\s*$exp_begin//; push @begin, $data;
if ($verbose) { if ($print_line_num) { $line_num = sprintf("%4s ", $.); } printf "%s %s%s%s\n", $prefix, $line_num, $timestamp, $line; }
next LINE; }
# ----- find EXPECT end
if ($line =~ /^\s*$exp_end/) { $data = $line; $data =~ s/^\s*$exp_end//;
if ($verbose) { if ($print_line_num) { $line_num = sprintf("%4s ", $.); } printf "%s %s%s%s\n", $prefix, $line_num, $timestamp, $line; }
$found = 0; $no_begin = 0; if (@found_or_begin > 0) { $begin = pop @found_or_begin; if (compare($data, $begin)) { $found = 1; } } elsif (@begin > 0) { $begin = pop @begin; } else { $no_begin = 1; }
if ($no_begin) {
print "** ERROR: EXPECT end without any EXPECT begin:\n"; print " end ---> $line\n";
} elsif (! $found) { if ($print_line_num) { $line_num = sprintf("%4s ", $.); }
printf "** %s%s$script_name WARNING - not found ---> %s\n", $line_num, $timestamp, $data;
} elsif (! compare($data, $begin)) { print "** ERROR: EXPECT end does not match EXPECT begin:\n"; print " begin -> $begin\n"; print " end ---> $line\n"; }
next LINE; }
# ----- not an EXPECT line
if (($line =~ /^${pr_fmt}start of unittest - you will see error messages$/) || ($line =~ /^${pr_fmt}end of unittest - [0-9]+ passed, [0-9]+ failed$/ ) ) { $prefix = "->"; # 2 characters } elsif ($line =~ /^${pr_fmt}FAIL /) { $prefix = ">>"; # 2 characters }
$found = 0; foreach $begin (@begin) { if (compare($begin, $line)) { $found = 1; last; } }
if ($found) { $begin = shift @begin; while (! compare($begin, $line)) { push @found_or_begin, $begin; $begin = shift @begin; } push @found_or_begin, $line;
if ($hide_expect) { $suppress_line = 1; next LINE; } $prefix = "ok"; # 2 characters }
if ($print_line_num) { $line_num = sprintf("%4s ", $.); }
printf "%s %s%s%s\n", $prefix, $line_num, $timestamp, $line; }
if (@begin) { print "** ERROR: EXPECT begin without any EXPECT end:\n"; print " This list may be misleading.\n"; foreach $begin (@begin) { print " begin ---> $begin\n"; } }
#______________________________________________________________________________ # - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - #_______________________________________________________________________________ # vi config follows:
# ~/.exrc must contain "set modelines" for tabs to be set automatically # ex:set tabstop=3 shiftwidth=3 sts=0:
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@CY4PR13MB11...
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.gitAn 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 500000-500000uV [ 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 1300000-1300000uV [ 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 2150000-2150000uV [ 2.534335] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: could not find phandle [ 2.534339] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 [ 2.544887] s3: supplied by regulator-dummy [ 2.548132] OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 [ 2.555433] s3: Bringing 0uV into 1800000-1800000uV [ 2.560266] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 [ 2.560270] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 [ 2.560298] OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 [ 2.560303] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 [ 2.560535] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1 [ 2.570510] l1: supplied by s1 [ 2.579510] OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1 [ 2.586682] l1: Bringing 0uV into 1225000-1225000uV [ 2.591521] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not get #phandle-missing-cells for /testcase-data/phandle-tests/provider1 [ 2.591525] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle [ 2.591587] OF: /testcase-data/phandle-tests/consumer-b: could not find phandle [ 2.601775] l2: supplied by s3 [ 2.611233] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: could not find phandle [ 2.611268] ### dt-test ### EXPECT \ : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1 [ 2.615419] l2: Bringing 0uV into 1200000-1200000uV [ 2.623396] OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1 [ 2.628271] l3: supplied by s1 [ 2.638063] ### dt-test ### EXPECT / : OF: /testcase-data/phandle-tests/consumer-b: #phandle-cells = 2 found -1 [ 2.640314] ### dt-test ### EXPECT \ : platform testcase-data:testcase-device2: IRQ index 0 not found [ 2.648179] l3: Bringing 0uV into 1225000-1225000uV [ 2.656092] platform testcase-data:testcase-device2: IRQ index 0 not found [ 2.666227] l4: supplied by s1 [ 2.680516] ### dt-test ### EXPECT / : platform testcase-data:testcase-device2: IRQ index 0 not found [ 2.686076] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status [ 2.696208] l4: Bringing 0uV into 1225000-1225000uV [ 2.700903] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status [ 2.834265] l5: supplied by s2 [ 2.836015] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest0/status [ 2.836019] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status [ 2.847318] l5: Bringing 0uV into 1800000-1800000uV [ 2.850356] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status [ 2.886261] l6: supplied by s2 [ 2.886399] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status [ 2.886404] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status [ 2.898903] l6: Bringing 0uV into 1800000-1800000uV [ 2.902539] sdhci_msm f98a4900.sdhci: Got CD GPIO [ 2.917894] l7: supplied by s2 [ 2.932924] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status [ 2.937295] l7: Bringing 0uV into 1800000-1800000uV [ 2.942841] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status [ 2.942846] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status [ 2.945614] l8: supplied by regulator-dummy [ 2.958650] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status [ 2.963000] l8: Bringing 0uV into 1800000-1800000uV [ 2.979086] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status [ 2.980440] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status [ 2.994350] l9: supplied by regulator-dummy [ 2.998308] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status [ 3.011109] l9: Bringing 0uV into 1800000-1800000uV [ 3.016696] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status [ 3.016850] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status [ 3.031831] l10: supplied by regulator-dummy [ 3.048351] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status [ 3.050677] l10: Bringing 0uV into 1800000-1800000uV [ 3.064441] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status [ 3.064446] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status [ 3.069011] l11: supplied by s1 [ 3.084690] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status [ 3.099536] l11: Bringing 0uV into 1300000-1300000uV [ 3.104432] sdhci_msm f98a4900.sdhci: Got CD GPIO [ 3.173762] l12: supplied by s2 [ 3.174105] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status [ 3.174972] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status [ 3.178158] l12: Bringing 0uV into 1800000-1800000uV [ 3.181186] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status [ 3.217801] l13: supplied by regulator-dummy [ 3.230269] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status [ 3.230275] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo [ 3.234444] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo [ 3.235079] sdhci_msm f98a4900.sdhci: Got CD GPIO [ 3.249677] l13: Bringing 0uV into 1800000-1800000uV [ 3.283658] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo [ 3.283662] ### dt-test ### EXPECT \ : OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8 [ 3.288738] ### dt-test ### EXPECT \ : OF: overlay: overlay #6 is not topmost [ 3.304462] OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8 [ 3.324871] OF: overlay: overlay #6 is not topmost [ 3.335975] ### dt-test ### EXPECT / : OF: overlay: overlay #6 is not topmost [ 3.335978] ### dt-test ### EXPECT / : OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8 [ 3.340707] l14: supplied by s2 [ 3.361105] l14: Bringing 0uV into 1800000-1800000uV [ 3.364354] l15: supplied by s2 [ 3.367222] ### dt-test ### EXPECT \ : i2c i2c-1: Added multiplexed i2c bus 2 [ 3.368029] i2c i2c-1: Added multiplexed i2c bus 2 [ 3.369217] l15: Bringing 0uV into 2050000-2050000uV [ 3.372488] ### dt-test ### EXPECT / : i2c i2c-1: Added multiplexed i2c bus 2 [ 3.372492] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status [ 3.379783] l16: supplied by regulator-dummy [ 3.384807] sdhci_msm f98a4900.sdhci: Got CD GPIO [ 3.389149] l16: Bringing 0uV into 2700000-2700000uV [ 3.396589] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status [ 3.427778] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status [ 3.427783] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status [ 3.427844] l17: supplied by regulator-dummy [ 3.440871] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status [ 3.457520] l17: Bringing 0uV into 2700000-2700000uV [ 3.475876] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status [ 3.475880] ### dt-test ### EXPECT \ : i2c i2c-1: Added multiplexed i2c bus 3 [ 3.478783] l18: supplied by regulator-dummy [ 3.497049] i2c i2c-1: Added multiplexed i2c bus 3 [ 3.497674] l18: Bringing 0uV into 2850000-2850000uV [ 3.514706] sdhci_msm f98a4900.sdhci: Got CD GPIO [ 3.521586] l19: supplied by regulator-dummy [ 3.525579] ### dt-test ### EXPECT / : i2c i2c-1: Added multiplexed i2c bus 3 [ 3.534279] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-B-input) hogged as input [ 3.535218] l19: Bringing 0uV into 3300000-3300000uV [ 3.540558] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-A-input) hogged as input [ 3.544881] l20: supplied by regulator-dummy [ 3.551751] GPIO line 315 (line-B-input) hogged as input [ 3.559114] l20: Bringing 0uV into 2950000-2950000uV [ 3.564560] GPIO line 309 (line-A-input) hogged as input [ 3.572690] l21: supplied by regulator-dummy [ 3.579102] ### dt-test ### EXPECT / : GPIO line <<int>> (line-A-input) hogged as input [ 3.581811] l21: Bringing 0uV into 2950000-2950000uV [ 3.586628] ### dt-test ### EXPECT / : GPIO line <<int>> (line-B-input) hogged as input [ 3.586633] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-D-input) hogged as input [ 3.592642] l22: supplied by regulator-dummy [ 3.600104] GPIO line 307 (line-D-input) hogged as input [ 3.604075] l22: Bringing 0uV into 3000000-3000000uV [ 3.609574] ### dt-test ### EXPECT / : GPIO line <<int>> (line-D-input) hogged as input [ 3.617292] l23: supplied by regulator-dummy [ 3.627709] ### dt-test ### EXPECT \ : GPIO line <<int>> (line-C-input) hogged as input [ 3.629414] l23: Bringing 0uV into 3000000-3000000uV [ 3.635770] ### dt-test ### EXPECT / : GPIO line <<int>> (line-C-input) hogged as input [ 3.640074] l24: supplied by regulator-dummy [ 3.647322] mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA [ 3.651912] l24: Bringing 0uV into 3075000-3075000uV [ 3.659592] ### dt-test ### FAIL of_unittest_overlay_gpio():2664 unittest_gpio_chip_request() called 0 times (expected 1 time) [ 3.665255] lvs1: supplied by s3 [ 3.682927] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status [ 3.682931] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status [ 3.684820] lvs2: supplied by s3 [ 3.690133] sdhci_msm f98a4900.sdhci: Got CD GPIO [ 3.700948] lvs3: supplied by s3 [ 3.704316] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up [ 3.704321] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up [ 3.718126] 5vs1: supplied by s4 [ 3.731723] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status [ 3.731727] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color [ 3.734472] 5vs2: supplied by s4 [ 3.738656] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate [ 3.738660] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2 [ 3.805410] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200 [ 3.818689] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left [ 3.830515] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right [ 3.843341] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status [ 3.860744] mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA [ 3.868094] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status [ 3.886817] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up [ 3.897848] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up [ 3.910448] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status [ 3.923033] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color [ 3.934061] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate [ 3.945320] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2 [ 3.956218] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200 [ 3.965748] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left [ 3.975753] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right [ 3.991170] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right [ 3.991174] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left [ 3.996032] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200 [ 4.008806] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2 [ 4.009664] msm_hsusb f9a55000.usb: failed to create device link to ci_hdrc.0.ulpi [ 4.021413] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate [ 4.021416] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color [ 4.052920] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status [ 4.066380] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up [ 4.079700] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up [ 4.093071] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status [ 4.108241] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status [ 4.123325] ### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller [ 4.136370] ### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name [ 4.150628] OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller [ 4.179147] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name [ 4.190137] ### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name [ 4.190145] ### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller [ 4.202662] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.217880] ### dt-test ### EXPECT \ : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.231256] ### dt-test ### EXPECT \ : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.231507] mmc1: new ultra high speed DDR50 SDHC card at address aaaa [ 4.246031] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.271061] mmcblk1: mmc1:aaaa SU16G 14.8 GiB [ 4.275021] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.298499] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.298507] mmcblk1: p1 [ 4.310625] ### dt-test ### EXPECT / : OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.310629] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.325399] ### dt-test ### EXPECT / : OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail [ 4.340232] ### dt-test ### end of unittest - 258 passed, 1 failed [ 4.369695] ALSA device list: [ 4.375127] No soundc�[ 4.382470] Freeing unused kernel memory: 1024K [ 4.392204] mmcblk0: mmc0:0001 SEM16G 14.7 GiB [ 4.392431] mmcblk0boot0: mmc0:0001 SEM16G partition 1 4.00 MiB [ 4.395717] mmcblk0boot1: mmc0:0001 SEM16G partition 2 4.00 MiB [ 4.401692] mmcblk0rpmb: mmc0:0001 SEM16G partition 3 4.00 MiB, chardev (247:0) [ 4.407818] Run /init as init process [ 4.416285] mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20 mkdir: can't create directory '/bin': File exists mkdir: can't create directory '/dev': File exists /init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory mdev: unknown user/group 'root:uucp' on line 34 Attempt to mount partitions: /usr/system /usr/data Mounting partitions from: /dev/mmcblk0 [ 4.912251] EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Opts: (null) [ 4.932285] EXT4-fs (mmcblk0p13): recovery complete [ 4.932321] EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Opts: (null) / # [ 5.288283] random: fast init done
/ # cat /proc/version Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020 / #
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@CY4PR13MB11...
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.gitAn 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 500000-500000uV 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 1300000-1300000uV 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 2150000-2150000uV s3: supplied by regulator-dummy ok OF: /testcase-data/phandle-tests/consumer-a: #phandle-cells = 3 found -1 s3: Bringing 0uV into 1800000-1800000uV 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 1200000-1200000uV 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 1800000-1800000uV ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest1/status l6: supplied by s2 l6: Bringing 0uV into 1800000-1800000uV sdhci_msm f98a4900.sdhci: Got CD GPIO l7: supplied by s2 ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest2/status l7: Bringing 0uV into 1800000-1800000uV l8: supplied by regulator-dummy ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest3/status l8: Bringing 0uV into 1800000-1800000uV l9: supplied by regulator-dummy ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest5/status l9: Bringing 0uV into 1800000-1800000uV l10: supplied by regulator-dummy ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest6/status l10: Bringing 0uV into 1800000-1800000uV l11: supplied by s1 ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest7/status l11: Bringing 0uV into 1300000-1300000uV sdhci_msm f98a4900.sdhci: Got CD GPIO l12: supplied by s2 l12: Bringing 0uV into 1800000-1800000uV ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/status l13: supplied by regulator-dummy ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/test-unittest8/property-foo sdhci_msm f98a4900.sdhci: Got CD GPIO l13: Bringing 0uV into 1800000-1800000uV ok OF: overlay: node_overlaps_later_cs: #6 overlaps with #7 @/testcase-data/overlay-node/test-bus/test-unittest8 ok OF: overlay: overlay #6 is not topmost l14: supplied by s2 l14: Bringing 0uV into 1800000-1800000uV l15: supplied by s2 ok i2c i2c-1: Added multiplexed i2c bus 2 l15: Bringing 0uV into 2050000-2050000uV l16: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO l16: Bringing 0uV into 2700000-2700000uV ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest12/status l17: supplied by regulator-dummy ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data/overlay-node/test-bus/i2c-test-bus/test-unittest13/status l17: Bringing 0uV into 2700000-2700000uV l18: supplied by regulator-dummy ok i2c i2c-1: Added multiplexed i2c bus 3 l18: Bringing 0uV into 2850000-2850000uV sdhci_msm f98a4900.sdhci: Got CD GPIO l19: supplied by regulator-dummy l19: Bringing 0uV into 3300000-3300000uV l20: supplied by regulator-dummy ok GPIO line 315 (line-B-input) hogged as input l20: Bringing 0uV into 2950000-2950000uV ok GPIO line 309 (line-A-input) hogged as input l21: supplied by regulator-dummy l21: Bringing 0uV into 2950000-2950000uV l22: supplied by regulator-dummy ok GPIO line 307 (line-D-input) hogged as input l22: Bringing 0uV into 3000000-3000000uV l23: supplied by regulator-dummy l23: Bringing 0uV into 3000000-3000000uV ** of_unittest_expect WARNING - not found ---> GPIO line <<int>> (line-C-input) hogged as input l24: supplied by regulator-dummy mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA l24: Bringing 0uV into 3075000-3075000uV
### dt-test ### FAIL of_unittest_overlay_gpio():2664 unittest_gpio_chip_request() called 0 times (expected 1 time)
lvs1: supplied by s3 lvs2: supplied by s3 sdhci_msm f98a4900.sdhci: Got CD GPIO lvs3: supplied by s3 5vs1: supplied by s4 5vs2: supplied by s4 ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/status mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/status ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@30/incline-up ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/fairway-1/ride@100/track@40/incline-up ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/status ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/color ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/lights@40000/rate ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/hvac_2 ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200 ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_left ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /__symbols__/ride_200_right msm_hsusb f9a55000.usb: failed to create device link to ci_hdrc.0.ulpi ok OF: overlay: ERROR: multiple fragments add and/or delete node /testcase-data-2/substation@100/motor-1/controller ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/controller/name mmc1: new ultra high speed DDR50 SDHC card at address aaaa ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail mmcblk1: mmc1:aaaa SU16G 14.8 GiB ok OF: overlay: WARNING: memory leak will occur if overlay removed, property: /testcase-data-2/substation@100/motor-1/rpm_avail ok OF: overlay: ERROR: multiple fragments add, update, and/or delete property /testcase-data-2/substation@100/motor-1/rpm_avail mmcblk1: p1 -> ### dt-test ### end of unittest - 258 passed, 1 failed ALSA device list: No soundc�[ 4.382470] Freeing unused kernel memory: 1024K mmcblk0: mmc0:0001 SEM16G 14.7 GiB mmcblk0boot0: mmc0:0001 SEM16G partition 1 4.00 MiB mmcblk0boot1: mmc0:0001 SEM16G partition 2 4.00 MiB mmcblk0rpmb: mmc0:0001 SEM16G partition 3 4.00 MiB, chardev (247:0) Run /init as init process mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20 mkdir: can't create directory '/bin': File exists mkdir: can't create directory '/dev': File exists /init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory mdev: unknown user/group 'root:uucp' on line 34 Attempt to mount partitions: /usr/system /usr/data Mounting partitions from: /dev/mmcblk0 EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Opts: (null) EXT4-fs (mmcblk0p13): recovery complete EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Opts: (null) / # [ 5.288283] random: fast init done
/ # cat /proc/version Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020 / #
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@CY4PR13MB11...
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.gitAn 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 500000-500000uV 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 1300000-1300000uV s2: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO s2: Bringing 0uV into 2150000-2150000uV s3: supplied by regulator-dummy s3: Bringing 0uV into 1800000-1800000uV l1: supplied by s1 l1: Bringing 0uV into 1225000-1225000uV l2: supplied by s3 l2: Bringing 0uV into 1200000-1200000uV 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 1800000-1800000uV l6: supplied by s2 l6: Bringing 0uV into 1800000-1800000uV sdhci_msm f98a4900.sdhci: Got CD GPIO l7: supplied by s2 l7: Bringing 0uV into 1800000-1800000uV l8: supplied by regulator-dummy l8: Bringing 0uV into 1800000-1800000uV l9: supplied by regulator-dummy l9: Bringing 0uV into 1800000-1800000uV l10: supplied by regulator-dummy l10: Bringing 0uV into 1800000-1800000uV l11: supplied by s1 l11: Bringing 0uV into 1300000-1300000uV sdhci_msm f98a4900.sdhci: Got CD GPIO l12: supplied by s2 l12: Bringing 0uV into 1800000-1800000uV l13: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO l13: Bringing 0uV into 1800000-1800000uV l14: supplied by s2 l14: Bringing 0uV into 1800000-1800000uV l15: supplied by s2 l15: Bringing 0uV into 2050000-2050000uV l16: supplied by regulator-dummy sdhci_msm f98a4900.sdhci: Got CD GPIO l16: Bringing 0uV into 2700000-2700000uV l17: supplied by regulator-dummy l17: Bringing 0uV into 2700000-2700000uV l18: supplied by regulator-dummy l18: Bringing 0uV into 2850000-2850000uV sdhci_msm f98a4900.sdhci: Got CD GPIO l19: supplied by regulator-dummy l19: Bringing 0uV into 3300000-3300000uV l20: supplied by regulator-dummy l20: Bringing 0uV into 2950000-2950000uV l21: supplied by regulator-dummy l21: Bringing 0uV into 2950000-2950000uV l22: supplied by regulator-dummy l22: Bringing 0uV into 3000000-3000000uV l23: supplied by regulator-dummy l23: Bringing 0uV into 3000000-3000000uV ** of_unittest_expect WARNING - not found ---> GPIO line <<int>> (line-C-input) hogged as input l24: supplied by regulator-dummy mmc0: SDHCI controller on f9824900.sdhci [f9824900.sdhci] using ADMA l24: Bringing 0uV into 3075000-3075000uV
### dt-test ### FAIL of_unittest_overlay_gpio():2664 unittest_gpio_chip_request() called 0 times (expected 1 time)
lvs1: supplied by s3 lvs2: supplied by s3 sdhci_msm f98a4900.sdhci: Got CD GPIO lvs3: supplied by s3 5vs1: supplied by s4 5vs2: supplied by s4 mmc1: SDHCI controller on f98a4900.sdhci [f98a4900.sdhci] using ADMA msm_hsusb f9a55000.usb: failed to create device link to ci_hdrc.0.ulpi mmc1: new ultra high speed DDR50 SDHC card at address aaaa mmcblk1: mmc1:aaaa SU16G 14.8 GiB mmcblk1: p1 -> ### dt-test ### end of unittest - 258 passed, 1 failed ALSA device list: No soundc�[ 4.382470] Freeing unused kernel memory: 1024K mmcblk0: mmc0:0001 SEM16G 14.7 GiB mmcblk0boot0: mmc0:0001 SEM16G partition 1 4.00 MiB mmcblk0boot1: mmc0:0001 SEM16G partition 2 4.00 MiB mmcblk0rpmb: mmc0:0001 SEM16G partition 3 4.00 MiB, chardev (247:0) Run /init as init process mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20 mkdir: can't create directory '/bin': File exists mkdir: can't create directory '/dev': File exists /init: line 25: can't create /proc/sys/kernel/hotplug: nonexistent directory mdev: unknown user/group 'root:uucp' on line 34 Attempt to mount partitions: /usr/system /usr/data Mounting partitions from: /dev/mmcblk0 EXT4-fs (mmcblk0p12): mounted filesystem with ordered data mode. Opts: (null) EXT4-fs (mmcblk0p13): recovery complete EXT4-fs (mmcblk0p13): mounted filesystem with ordered data mode. Opts: (null) / # [ 5.288283] random: fast init done
/ # cat /proc/version Linux version 5.6.0-rc1-00002-g6be01ed870a2-dirty (frowand@xps8900) (gcc version 4.6.x-google 20120106 (prerelease) (GCC)) #4 SMP PREEMPT Wed Feb 19 18:23:24 CST 2020 / #
On Mon, Jun 22, 2020 at 6:45 AM Frank Rowand frowand.list@gmail.com 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@CY4PR13MB11...
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.gitAn 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
On Mon, Jun 22, 2020 at 7:47 PM David Gow davidgow@google.com wrote:
On Mon, Jun 22, 2020 at 6:45 AM Frank Rowand frowand.list@gmail.com 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@CY4PR13MB11...
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.
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.gitAn 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
+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 frowand.list@gmail.com 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@CY4PR13MB11...
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 output manually).
-Frank
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.gitAn 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
On Tue, 23 Jun 2020, David Gow wrote:
On Mon, Jun 22, 2020 at 6:45 AM Frank Rowand frowand.list@gmail.com 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@CY4PR13MB11...
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.
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
linux-kselftest-mirror@lists.linaro.org
-
Alan Maguire -
Bird, Tim -
Brendan Higgins -
David Gow -
Frank Rowand