RFC: KTAP documentation - expected messages

RFC: KTAP documentation - expected messages

[Frank Rowand]

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@CY4PR13MB1175.namprd13.prod.outlook.com

The issue of messages generated by the kernel being tested (that are not
messages directly created by the tests, but are instead triggered as a
side effect of the test) came up.  In this thread, I will call these
messages "expected messages".  Instead of sidetracking that thread with
a proposal to handle expected messages, I am starting this new thread.

I implemented an API for expected messages that are triggered by tests
in the Devicetree unittest code, with the expectation that the specific
details may change when the Devicetree unittest code adapts the KUnit
API.  It seems appropriate to incorporate the concept of expected
messages in Tim's documentation instead of waiting to address the
subject when the Devicetree unittest code adapts the KUnit API, since
Tim's document may become the kernel selftest standard.

Instead of creating a very long email containing multiple objects,
I will reply to this email with a separate reply for each of:

  The "expected messages" API implemention and use can be from
  drivers/of/unittest.c in the mainline kernel.

  of_unittest_expect - A proof of concept perl program to filter console
                       output containing expected messages output

                       of_unittest_expect is also available by cloning
                       https://github.com/frowand/dt_tools.git

  An example raw console output with timestamps and expect messages.

  An example of console output processed by filter program
  of_unittest_expect to be more human readable.  The expected
  messages are not removed, but are flagged.

  An example of console output processed by filter program
  of_unittest_expect to be more human readable.  The expected
  messages are removed instead of being flagged.

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> 
> The issue of messages generated by the kernel being tested (that are not
> messages directly created by the tests, but are instead triggered as a
> side effect of the test) came up.  In this thread, I will call these
> messages "expected messages".  Instead of sidetracking that thread with
> a proposal to handle expected messages, I am starting this new thread.
> 
> I implemented an API for expected messages that are triggered by tests
> in the Devicetree unittest code, with the expectation that the specific
> details may change when the Devicetree unittest code adapts the KUnit
> API.  It seems appropriate to incorporate the concept of expected
> messages in Tim's documentation instead of waiting to address the
> subject when the Devicetree unittest code adapts the KUnit API, since
> Tim's document may become the kernel selftest standard.
> 
> Instead of creating a very long email containing multiple objects,
> I will reply to this email with a separate reply for each of:
> 
>   The "expected messages" API implemention and use can be from
>   drivers/of/unittest.c in the mainline kernel.
> 
>   of_unittest_expect - A proof of concept perl program to filter console
>                        output containing expected messages output
> 
>                        of_unittest_expect is also available by cloning
>                        https://github.com/frowand/dt_tools.git
> 
>   An example raw console output with timestamps and expect messages.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are not removed, but are flagged.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are removed instead of being flagged.
> 

reply 1/5

expected messages API:

  - execute EXPECT_BEGIN(), reporting the expected message, before the
    point when the message will occur

  - execute EXPECT_END(), reporting the same expected message, after the
    point when the message will occur

  - EXPECT_BEGIN() may occur multiple times, before the corresponding
    EXPECT_END()s, when a single test action may result in multiple
    expected messages

  - When multiple EXPECT_BEGIN()s are nested, the corresponding (matching)
    EXPECT_END()s occur in the inverse order of the EXPECT_BEGIN()s.

  - When the expected message contain a non-constant value, a place holder
    can be placed in the message.  Current place holders are:

     - <<int>>  an integer
     - <<hex>>  a hexadecimal number

     Suggested additional place holder(s) are:

       - <<alpha>>  contiguous non white space characters 

       I have avoided allowing regular expessions, because test frameworks
       may implement their own filtering instead of relying on a generic
       console output filter program.  There are multiple definitions for
       regular expressions in different languages, thus it could be
       difficult to set rules for a subset of regular expression usable
       by all languages.

A preliminary version of an expected messages framework has been
implemented in the mainline drivers/of/unittest.c.  The implementation
is trivial, as seen below.

Note that the define of "pr_fmt()" pre-dates the implementation
of the EXPECT_BEGIN() and EXPECT_END() macros.
---------------------------------------------------------------

#define pr_fmt(fmt) "### dt-test ### " fmt


/*
 * Expected message may have a message level other than KERN_INFO.
 * Print the expected message only if the current loglevel will allow
 * the actual message to print.
 *
 * Do not use EXPECT_BEGIN() or EXPECT_END() for messages generated by
 * pr_debug().
 */
#define EXPECT_BEGIN(level, fmt, ...) \
        printk(level pr_fmt("EXPECT \\ : ") fmt, ##__VA_ARGS__)

#define EXPECT_END(level, fmt, ...) \
        printk(level pr_fmt("EXPECT / : ") fmt, ##__VA_ARGS__)



Example 1 of the API use, single message:
-----------------------------------------

        EXPECT_BEGIN(KERN_INFO,
                     "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");

        rc = of_parse_phandle_with_args(np, "phandle-list-bad-phandle",
                                        "#phandle-cells", 0, &args);

        EXPECT_END(KERN_INFO,
                   "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");


Example 2 of the API use, two messages,
"<<int>>" placeholder matches any integer:
------------------------------------------

        /*
         * messages are the result of the probes, after the
         * driver is registered
         */

        EXPECT_BEGIN(KERN_INFO,
                     "GPIO line <<int>> (line-B-input) hogged as input\n");

        EXPECT_BEGIN(KERN_INFO,
                     "GPIO line <<int>> (line-A-input) hogged as input\n");

        ret = platform_driver_register(&unittest_gpio_driver);
        if (unittest(ret == 0, "could not register unittest gpio driver\n"))
                return;

        EXPECT_END(KERN_INFO,
                   "GPIO line <<int>> (line-A-input) hogged as input\n");
        EXPECT_END(KERN_INFO,
                   "GPIO line <<int>> (line-B-input) hogged as input\n");

Subtle flow of control issue: the two EXPECT_END() are not executed if
platform_driver_register() fails.  The two expected messages will not
be printed, but the filter tool (of_unittest_expect) will not report this
as an error because of_unittest_expect does not search for the messages
until the EXPEND_END() output is encountered.

One could argue that this is correct behavior because unittest() will print
the error that platform_driver_register() failed.  The "expected" messages
are not expected if the register fails.

One could equally well argue that the two EXPECT_END() should execute
before unittest() checks the value of ret, so the missing messages will
be reported as an error by of_unittest_expect.

But that is a discussion that should occur in the context of whether
drivers/of/unittest.c has a coding error, not in the context of how
to implement the expected messages framework.


goals:

  - The console output should be human readable and easy to parse.
    Have "\" in the expect begin and a matching "/" in the expect end
    is intended to make it easier to visualize pairs.

  - The console output should be machine parsable.


Design alternate choices:

  - Expect message nesting:
     1) Nested expect messages place the "\" in the same column.
     2) For each nested expect message, indent the "\" by one more column
        for each level of nesting.

    Chose 1.  This keeps the EXPECT_BEGIN() and EXPECT_END() macros very
    simple, at the expense of the output being less human readable in the
    raw log.

    The raw log is already not very readable, and I would expect the normal
    use case would be using a filter program, such as of_unittest_expect,
    to handle the readability issue.


Issues:

  - The EXPECT_BEGIN() and EXPECT_END() macros use printk() for output.
    printk() prefixes the output with the value of the pr_fmt() macro.
    This means the filter program must be able to deal with different
    pr_fmt() strings being incorporated in the expect messages that
    are in different source files.  The unittest.c pr_fmt() value is
    currently hard coded in the of_unittest_expect filter program.

  - The output of the of_unittest_expect filter program prepends several
    columns of data at the beginning of the resulting filtered data.  The
    TAP format does not expect these extra columns.

    The prepended data is very important for making the report easily
    read by humans.

    1) It will be trivial to add an of_unittest_expect "--tap-out" option
       to not add the prepended data, so that normal TAP programs can use
       the output from of_unittest_expect.

    2) The "--tap-out" option could also create a TAP "test line" reporting
       an "ok" for expected message detected and "not ok" if an expected
       message is not detected.

       This would also require modifying the "test plan" line to change
       the number of tests.

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

On 2020-06-21 17:49, Frank Rowand wrote:
> On 2020-06-21 17:45, Frank Rowand wrote:
>> Tim Bird started a thread [1] proposing that he document the selftest result
>> format used by Linux kernel tests.  
>>
>> [1] https://lore.kernel.org/r/CY4PR13MB1175B804E31E502221BC8163FD830@CY4PR13MB1175.namprd13.prod.outlook.com
>>
>> The issue of messages generated by the kernel being tested (that are not
>> messages directly created by the tests, but are instead triggered as a
>> side effect of the test) came up.  In this thread, I will call these
>> messages "expected messages".  Instead of sidetracking that thread with
>> a proposal to handle expected messages, I am starting this new thread.
>>
>> I implemented an API for expected messages that are triggered by tests
>> in the Devicetree unittest code, with the expectation that the specific
>> details may change when the Devicetree unittest code adapts the KUnit
>> API.  It seems appropriate to incorporate the concept of expected
>> messages in Tim's documentation instead of waiting to address the
>> subject when the Devicetree unittest code adapts the KUnit API, since
>> Tim's document may become the kernel selftest standard.
>>
>> Instead of creating a very long email containing multiple objects,
>> I will reply to this email with a separate reply for each of:
>>
>>   The "expected messages" API implemention and use can be from
>>   drivers/of/unittest.c in the mainline kernel.
>>
>>   of_unittest_expect - A proof of concept perl program to filter console
>>                        output containing expected messages output
>>
>>                        of_unittest_expect is also available by cloning
>>                        https://github.com/frowand/dt_tools.git
>>
>>   An example raw console output with timestamps and expect messages.
>>
>>   An example of console output processed by filter program
>>   of_unittest_expect to be more human readable.  The expected
>>   messages are not removed, but are flagged.
>>
>>   An example of console output processed by filter program
>>   of_unittest_expect to be more human readable.  The expected
>>   messages are removed instead of being flagged.
>>
> 
> reply 1/5
> 
> expected messages API:
> 
>   - execute EXPECT_BEGIN(), reporting the expected message, before the
>     point when the message will occur
> 
>   - execute EXPECT_END(), reporting the same expected message, after the
>     point when the message will occur
> 
>   - EXPECT_BEGIN() may occur multiple times, before the corresponding
>     EXPECT_END()s, when a single test action may result in multiple
>     expected messages
> 
>   - When multiple EXPECT_BEGIN()s are nested, the corresponding (matching)
>     EXPECT_END()s occur in the inverse order of the EXPECT_BEGIN()s.
> 
>   - When the expected message contain a non-constant value, a place holder
>     can be placed in the message.  Current place holders are:
> 
>      - <<int>>  an integer
>      - <<hex>>  a hexadecimal number
> 
>      Suggested additional place holder(s) are:
> 
>        - <<alpha>>  contiguous non white space characters 
> 
>        I have avoided allowing regular expessions, because test frameworks
>        may implement their own filtering instead of relying on a generic
>        console output filter program.  There are multiple definitions for
>        regular expressions in different languages, thus it could be
>        difficult to set rules for a subset of regular expression usable
>        by all languages.
> 
> A preliminary version of an expected messages framework has been
> implemented in the mainline drivers/of/unittest.c.  The implementation
> is trivial, as seen below.
> 
> Note that the define of "pr_fmt()" pre-dates the implementation
> of the EXPECT_BEGIN() and EXPECT_END() macros.
> ---------------------------------------------------------------
> 
> #define pr_fmt(fmt) "### dt-test ### " fmt
> 
> 
> /*
>  * Expected message may have a message level other than KERN_INFO.
>  * Print the expected message only if the current loglevel will allow
>  * the actual message to print.
>  *
>  * Do not use EXPECT_BEGIN() or EXPECT_END() for messages generated by
>  * pr_debug().
>  */
> #define EXPECT_BEGIN(level, fmt, ...) \
>         printk(level pr_fmt("EXPECT \\ : ") fmt, ##__VA_ARGS__)
> 
> #define EXPECT_END(level, fmt, ...) \
>         printk(level pr_fmt("EXPECT / : ") fmt, ##__VA_ARGS__)

I included the pr_fmt() in EXPECT_BEGIN() and EXPECT_END(), because I
defined the two macros within the unittest.c file.

For a KTAP compliant generic implementation, I would change these
to be diagnostic messages, so:

  #define EXPECT_BEGIN(level, fmt, ...) \
          printk(level "# EXPECT \\ : " fmt, ##__VA_ARGS__)
  
  #define EXPECT_END(level, fmt, ...) \
          printk(level "# EXPECT / : " fmt, ##__VA_ARGS__)

This also fixes the first issue in the "Issues" list below.

-Frank

> 
> 
> 
> Example 1 of the API use, single message:
> -----------------------------------------
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> 
>         rc = of_parse_phandle_with_args(np, "phandle-list-bad-phandle",
>                                         "#phandle-cells", 0, &args);
> 
>         EXPECT_END(KERN_INFO,
>                    "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> 
> 
> Example 2 of the API use, two messages,
> "<<int>>" placeholder matches any integer:
> ------------------------------------------
> 
>         /*
>          * messages are the result of the probes, after the
>          * driver is registered
>          */
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "GPIO line <<int>> (line-B-input) hogged as input\n");
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "GPIO line <<int>> (line-A-input) hogged as input\n");
> 
>         ret = platform_driver_register(&unittest_gpio_driver);
>         if (unittest(ret == 0, "could not register unittest gpio driver\n"))
>                 return;
> 
>         EXPECT_END(KERN_INFO,
>                    "GPIO line <<int>> (line-A-input) hogged as input\n");
>         EXPECT_END(KERN_INFO,
>                    "GPIO line <<int>> (line-B-input) hogged as input\n");
> 
> Subtle flow of control issue: the two EXPECT_END() are not executed if
> platform_driver_register() fails.  The two expected messages will not
> be printed, but the filter tool (of_unittest_expect) will not report this
> as an error because of_unittest_expect does not search for the messages
> until the EXPEND_END() output is encountered.
> 
> One could argue that this is correct behavior because unittest() will print
> the error that platform_driver_register() failed.  The "expected" messages
> are not expected if the register fails.
> 
> One could equally well argue that the two EXPECT_END() should execute
> before unittest() checks the value of ret, so the missing messages will
> be reported as an error by of_unittest_expect.
> 
> But that is a discussion that should occur in the context of whether
> drivers/of/unittest.c has a coding error, not in the context of how
> to implement the expected messages framework.
> 
> 
> goals:
> 
>   - The console output should be human readable and easy to parse.
>     Have "\" in the expect begin and a matching "/" in the expect end
>     is intended to make it easier to visualize pairs.
> 
>   - The console output should be machine parsable.
> 
> 
> Design alternate choices:
> 
>   - Expect message nesting:
>      1) Nested expect messages place the "\" in the same column.
>      2) For each nested expect message, indent the "\" by one more column
>         for each level of nesting.
> 
>     Chose 1.  This keeps the EXPECT_BEGIN() and EXPECT_END() macros very
>     simple, at the expense of the output being less human readable in the
>     raw log.
> 
>     The raw log is already not very readable, and I would expect the normal
>     use case would be using a filter program, such as of_unittest_expect,
>     to handle the readability issue.
> 
> 
> Issues:
> 
>   - The EXPECT_BEGIN() and EXPECT_END() macros use printk() for output.
>     printk() prefixes the output with the value of the pr_fmt() macro.
>     This means the filter program must be able to deal with different
>     pr_fmt() strings being incorporated in the expect messages that
>     are in different source files.  The unittest.c pr_fmt() value is
>     currently hard coded in the of_unittest_expect filter program.
> 
>   - The output of the of_unittest_expect filter program prepends several
>     columns of data at the beginning of the resulting filtered data.  The
>     TAP format does not expect these extra columns.
> 
>     The prepended data is very important for making the report easily
>     read by humans.
> 
>     1) It will be trivial to add an of_unittest_expect "--tap-out" option
>        to not add the prepended data, so that normal TAP programs can use
>        the output from of_unittest_expect.
> 
>     2) The "--tap-out" option could also create a TAP "test line" reporting
>        an "ok" for expected message detected and "not ok" if an expected
>        message is not detected.
> 
>        This would also require modifying the "test plan" line to change
>        the number of tests.
> 

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

On 2020-06-21 17:49, Frank Rowand wrote:
> On 2020-06-21 17:45, Frank Rowand wrote:
>> Tim Bird started a thread [1] proposing that he document the selftest result
>> format used by Linux kernel tests.  
>>
>> [1] https://lore.kernel.org/r/CY4PR13MB1175B804E31E502221BC8163FD830@CY4PR13MB1175.namprd13.prod.outlook.com
>>
>> The issue of messages generated by the kernel being tested (that are not
>> messages directly created by the tests, but are instead triggered as a
>> side effect of the test) came up.  In this thread, I will call these
>> messages "expected messages".  Instead of sidetracking that thread with
>> a proposal to handle expected messages, I am starting this new thread.
>>
>> I implemented an API for expected messages that are triggered by tests
>> in the Devicetree unittest code, with the expectation that the specific
>> details may change when the Devicetree unittest code adapts the KUnit
>> API.  It seems appropriate to incorporate the concept of expected
>> messages in Tim's documentation instead of waiting to address the
>> subject when the Devicetree unittest code adapts the KUnit API, since
>> Tim's document may become the kernel selftest standard.
>>
>> Instead of creating a very long email containing multiple objects,
>> I will reply to this email with a separate reply for each of:
>>
>>   The "expected messages" API implemention and use can be from
>>   drivers/of/unittest.c in the mainline kernel.
>>
>>   of_unittest_expect - A proof of concept perl program to filter console
>>                        output containing expected messages output
>>
>>                        of_unittest_expect is also available by cloning
>>                        https://github.com/frowand/dt_tools.git
>>
>>   An example raw console output with timestamps and expect messages.
>>
>>   An example of console output processed by filter program
>>   of_unittest_expect to be more human readable.  The expected
>>   messages are not removed, but are flagged.
>>
>>   An example of console output processed by filter program
>>   of_unittest_expect to be more human readable.  The expected
>>   messages are removed instead of being flagged.
>>
> 
> reply 1/5
> 
> expected messages API:
> 
>   - execute EXPECT_BEGIN(), reporting the expected message, before the
>     point when the message will occur
> 
>   - execute EXPECT_END(), reporting the same expected message, after the
>     point when the message will occur
> 
>   - EXPECT_BEGIN() may occur multiple times, before the corresponding
>     EXPECT_END()s, when a single test action may result in multiple
>     expected messages
> 
>   - When multiple EXPECT_BEGIN()s are nested, the corresponding (matching)
>     EXPECT_END()s occur in the inverse order of the EXPECT_BEGIN()s.
> 
>   - When the expected message contain a non-constant value, a place holder
>     can be placed in the message.  Current place holders are:
> 
>      - <<int>>  an integer
>      - <<hex>>  a hexadecimal number
> 
>      Suggested additional place holder(s) are:
> 
>        - <<alpha>>  contiguous non white space characters 
> 
>        I have avoided allowing regular expessions, because test frameworks
>        may implement their own filtering instead of relying on a generic
>        console output filter program.  There are multiple definitions for
>        regular expressions in different languages, thus it could be
>        difficult to set rules for a subset of regular expression usable
>        by all languages.
> 
> A preliminary version of an expected messages framework has been
> implemented in the mainline drivers/of/unittest.c.  The implementation
> is trivial, as seen below.
> 
> Note that the define of "pr_fmt()" pre-dates the implementation
> of the EXPECT_BEGIN() and EXPECT_END() macros.
> ---------------------------------------------------------------
> 
> #define pr_fmt(fmt) "### dt-test ### " fmt
> 
> 
> /*
>  * Expected message may have a message level other than KERN_INFO.
>  * Print the expected message only if the current loglevel will allow
>  * the actual message to print.
>  *
>  * Do not use EXPECT_BEGIN() or EXPECT_END() for messages generated by
>  * pr_debug().
>  */
> #define EXPECT_BEGIN(level, fmt, ...) \
>         printk(level pr_fmt("EXPECT \\ : ") fmt, ##__VA_ARGS__)
> 
> #define EXPECT_END(level, fmt, ...) \
>         printk(level pr_fmt("EXPECT / : ") fmt, ##__VA_ARGS__)
> 
> 
> 
> Example 1 of the API use, single message:
> -----------------------------------------
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> 
>         rc = of_parse_phandle_with_args(np, "phandle-list-bad-phandle",
>                                         "#phandle-cells", 0, &args);
> 
>         EXPECT_END(KERN_INFO,
>                    "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> 
> 
> Example 2 of the API use, two messages,
> "<<int>>" placeholder matches any integer:
> ------------------------------------------
> 
>         /*
>          * messages are the result of the probes, after the
>          * driver is registered
>          */
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "GPIO line <<int>> (line-B-input) hogged as input\n");
> 
>         EXPECT_BEGIN(KERN_INFO,
>                      "GPIO line <<int>> (line-A-input) hogged as input\n");
> 
>         ret = platform_driver_register(&unittest_gpio_driver);
>         if (unittest(ret == 0, "could not register unittest gpio driver\n"))
>                 return;
> 
>         EXPECT_END(KERN_INFO,
>                    "GPIO line <<int>> (line-A-input) hogged as input\n");
>         EXPECT_END(KERN_INFO,
>                    "GPIO line <<int>> (line-B-input) hogged as input\n");
> 
> Subtle flow of control issue: the two EXPECT_END() are not executed if
> platform_driver_register() fails.  The two expected messages will not
> be printed, but the filter tool (of_unittest_expect) will not report this
> as an error because of_unittest_expect does not search for the messages
> until the EXPEND_END() output is encountered.
> 
> One could argue that this is correct behavior because unittest() will print
> the error that platform_driver_register() failed.  The "expected" messages
> are not expected if the register fails.
> 
> One could equally well argue that the two EXPECT_END() should execute
> before unittest() checks the value of ret, so the missing messages will
> be reported as an error by of_unittest_expect.
> 
> But that is a discussion that should occur in the context of whether
> drivers/of/unittest.c has a coding error, not in the context of how
> to implement the expected messages framework.
> 
> 
> goals:
> 
>   - The console output should be human readable and easy to parse.
>     Have "\" in the expect begin and a matching "/" in the expect end
>     is intended to make it easier to visualize pairs.
> 
>   - The console output should be machine parsable.
> 
> 
> Design alternate choices:
> 
>   - Expect message nesting:
>      1) Nested expect messages place the "\" in the same column.
>      2) For each nested expect message, indent the "\" by one more column
>         for each level of nesting.
> 
>     Chose 1.  This keeps the EXPECT_BEGIN() and EXPECT_END() macros very
>     simple, at the expense of the output being less human readable in the
>     raw log.
> 
>     The raw log is already not very readable, and I would expect the normal
>     use case would be using a filter program, such as of_unittest_expect,
>     to handle the readability issue.
> 
> 
> Issues:
> 
>   - The EXPECT_BEGIN() and EXPECT_END() macros use printk() for output.
>     printk() prefixes the output with the value of the pr_fmt() macro.
>     This means the filter program must be able to deal with different
>     pr_fmt() strings being incorporated in the expect messages that
>     are in different source files.  The unittest.c pr_fmt() value is
>     currently hard coded in the of_unittest_expect filter program.
> 
>   - The output of the of_unittest_expect filter program prepends several
>     columns of data at the beginning of the resulting filtered data.  The
>     TAP format does not expect these extra columns.
> 
>     The prepended data is very important for making the report easily
>     read by humans.
> 
>     1) It will be trivial to add an of_unittest_expect "--tap-out" option
>        to not add the prepended data, so that normal TAP programs can use
>        the output from of_unittest_expect.
> 
>     2) The "--tap-out" option could also create a TAP "test line" reporting
>        an "ok" for expected message detected and "not ok" if an expected
>        message is not detected.
> 
>        This would also require modifying the "test plan" line to change
>        the number of tests.
> 
  - KUnit already has a concept that uses the word "expect".  A test may
    have expectations about what the data created or modified by the test
    will be.  For example, if the test invokes:

       ret = add(3, 4)

    then the test might expect ret to contain the value "7".  If it does
    not, then the test could report:

       ret = add(14, -7)
       expected ret == 7, but instead ret == -22

    (Don't take this example as a valid KUnit format, I just trying to
    explain the concept.)

    The word EXPECT in this new feature should be changed to something else
    to avoid confusion with the other KUnit concept.  Or alternately,
    KUnit could change the word used for its existing concept, if that
    is an easier change.

RE: RFC: KTAP documentation - expected messages

[Bird, Tim]

> -----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@CY4PR13MB1175.namprd13.prod.outlook.com
> >>
> >> The issue of messages generated by the kernel being tested (that are not
> >> messages directly created by the tests, but are instead triggered as a
> >> side effect of the test) came up.  In this thread, I will call these
> >> messages "expected messages".  Instead of sidetracking that thread with
> >> a proposal to handle expected messages, I am starting this new thread.
> >>
> >> I implemented an API for expected messages that are triggered by tests
> >> in the Devicetree unittest code, with the expectation that the specific
> >> details may change when the Devicetree unittest code adapts the KUnit
> >> API.  It seems appropriate to incorporate the concept of expected
> >> messages in Tim's documentation instead of waiting to address the
> >> subject when the Devicetree unittest code adapts the KUnit API, since
> >> Tim's document may become the kernel selftest standard.
> >>
> >> Instead of creating a very long email containing multiple objects,
> >> I will reply to this email with a separate reply for each of:
> >>
> >>   The "expected messages" API implemention and use can be from
> >>   drivers/of/unittest.c in the mainline kernel.
> >>
> >>   of_unittest_expect - A proof of concept perl program to filter console
> >>                        output containing expected messages output
> >>
> >>                        of_unittest_expect is also available by cloning
> >>                        https://github.com/frowand/dt_tools.git
> >>
> >>   An example raw console output with timestamps and expect messages.
> >>
> >>   An example of console output processed by filter program
> >>   of_unittest_expect to be more human readable.  The expected
> >>   messages are not removed, but are flagged.
> >>
> >>   An example of console output processed by filter program
> >>   of_unittest_expect to be more human readable.  The expected
> >>   messages are removed instead of being flagged.
> >>
> >
> > reply 1/5
> >
> > expected messages API:
> >
> >   - execute EXPECT_BEGIN(), reporting the expected message, before the
> >     point when the message will occur
> >
> >   - execute EXPECT_END(), reporting the same expected message, after the
> >     point when the message will occur
> >
> >   - EXPECT_BEGIN() may occur multiple times, before the corresponding
> >     EXPECT_END()s, when a single test action may result in multiple
> >     expected messages
> >
> >   - When multiple EXPECT_BEGIN()s are nested, the corresponding (matching)
> >     EXPECT_END()s occur in the inverse order of the EXPECT_BEGIN()s.
> >
> >   - When the expected message contain a non-constant value, a place holder
> >     can be placed in the message.  Current place holders are:
> >
> >      - <<int>>  an integer
> >      - <<hex>>  a hexadecimal number
> >
> >      Suggested additional place holder(s) are:
> >
> >        - <<alpha>>  contiguous non white space characters
> >
> >        I have avoided allowing regular expessions, because test frameworks
> >        may implement their own filtering instead of relying on a generic
> >        console output filter program.  There are multiple definitions for
> >        regular expressions in different languages, thus it could be
> >        difficult to set rules for a subset of regular expression usable
> >        by all languages.
> >
> > A preliminary version of an expected messages framework has been
> > implemented in the mainline drivers/of/unittest.c.  The implementation
> > is trivial, as seen below.
> >
> > Note that the define of "pr_fmt()" pre-dates the implementation
> > of the EXPECT_BEGIN() and EXPECT_END() macros.
> > ---------------------------------------------------------------
> >
> > #define pr_fmt(fmt) "### dt-test ### " fmt
> >
> >
> > /*
> >  * Expected message may have a message level other than KERN_INFO.
> >  * Print the expected message only if the current loglevel will allow
> >  * the actual message to print.
> >  *
> >  * Do not use EXPECT_BEGIN() or EXPECT_END() for messages generated by
> >  * pr_debug().
> >  */
> > #define EXPECT_BEGIN(level, fmt, ...) \
> >         printk(level pr_fmt("EXPECT \\ : ") fmt, ##__VA_ARGS__)
> >
> > #define EXPECT_END(level, fmt, ...) \
> >         printk(level pr_fmt("EXPECT / : ") fmt, ##__VA_ARGS__)
> >
> >
> >
> > Example 1 of the API use, single message:
> > -----------------------------------------
> >
> >         EXPECT_BEGIN(KERN_INFO,
> >                      "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> >
> >         rc = of_parse_phandle_with_args(np, "phandle-list-bad-phandle",
> >                                         "#phandle-cells", 0, &args);
> >
> >         EXPECT_END(KERN_INFO,
> >                    "OF: /testcase-data/phandle-tests/consumer-a: could not find phandle");
> >
> >
> > Example 2 of the API use, two messages,
> > "<<int>>" placeholder matches any integer:
> > ------------------------------------------
> >
> >         /*
> >          * messages are the result of the probes, after the
> >          * driver is registered
> >          */
> >
> >         EXPECT_BEGIN(KERN_INFO,
> >                      "GPIO line <<int>> (line-B-input) hogged as input\n");
> >
> >         EXPECT_BEGIN(KERN_INFO,
> >                      "GPIO line <<int>> (line-A-input) hogged as input\n");
> >
> >         ret = platform_driver_register(&unittest_gpio_driver);
> >         if (unittest(ret == 0, "could not register unittest gpio driver\n"))
> >                 return;
> >
> >         EXPECT_END(KERN_INFO,
> >                    "GPIO line <<int>> (line-A-input) hogged as input\n");
> >         EXPECT_END(KERN_INFO,
> >                    "GPIO line <<int>> (line-B-input) hogged as input\n");
> >
> > Subtle flow of control issue: the two EXPECT_END() are not executed if
> > platform_driver_register() fails.  The two expected messages will not
> > be printed, but the filter tool (of_unittest_expect) will not report this
> > as an error because of_unittest_expect does not search for the messages
> > until the EXPEND_END() output is encountered.
> >
> > One could argue that this is correct behavior because unittest() will print
> > the error that platform_driver_register() failed.  The "expected" messages
> > are not expected if the register fails.
> >
> > One could equally well argue that the two EXPECT_END() should execute
> > before unittest() checks the value of ret, so the missing messages will
> > be reported as an error by of_unittest_expect.
> >
> > But that is a discussion that should occur in the context of whether
> > drivers/of/unittest.c has a coding error, not in the context of how
> > to implement the expected messages framework.
> >
> >
> > goals:
> >
> >   - The console output should be human readable and easy to parse.
> >     Have "\" in the expect begin and a matching "/" in the expect end
> >     is intended to make it easier to visualize pairs.
> >
> >   - The console output should be machine parsable.
> >
> >
> > Design alternate choices:
> >
> >   - Expect message nesting:
> >      1) Nested expect messages place the "\" in the same column.
> >      2) For each nested expect message, indent the "\" by one more column
> >         for each level of nesting.
> >
> >     Chose 1.  This keeps the EXPECT_BEGIN() and EXPECT_END() macros very
> >     simple, at the expense of the output being less human readable in the
> >     raw log.
> >
> >     The raw log is already not very readable, and I would expect the normal
> >     use case would be using a filter program, such as of_unittest_expect,
> >     to handle the readability issue.
> >
> >
> > Issues:
> >
> >   - The EXPECT_BEGIN() and EXPECT_END() macros use printk() for output.
> >     printk() prefixes the output with the value of the pr_fmt() macro.
> >     This means the filter program must be able to deal with different
> >     pr_fmt() strings being incorporated in the expect messages that
> >     are in different source files.  The unittest.c pr_fmt() value is
> >     currently hard coded in the of_unittest_expect filter program.
> >
> >   - The output of the of_unittest_expect filter program prepends several
> >     columns of data at the beginning of the resulting filtered data.  The
> >     TAP format does not expect these extra columns.
> >
> >     The prepended data is very important for making the report easily
> >     read by humans.
> >
> >     1) It will be trivial to add an of_unittest_expect "--tap-out" option
> >        to not add the prepended data, so that normal TAP programs can use
> >        the output from of_unittest_expect.
> >
> >     2) The "--tap-out" option could also create a TAP "test line" reporting
> >        an "ok" for expected message detected and "not ok" if an expected
> >        message is not detected.
> >
> >        This would also require modifying the "test plan" line to change
> >        the number of tests.
> >
>   - KUnit already has a concept that uses the word "expect".  A test may
>     have expectations about what the data created or modified by the test
>     will be.  For example, if the test invokes:
> 
>        ret = add(3, 4)
> 
>     then the test might expect ret to contain the value "7".  If it does
>     not, then the test could report:
> 
>        ret = add(14, -7)
>        expected ret == 7, but instead ret == -22
> 
>     (Don't take this example as a valid KUnit format, I just trying to
>     explain the concept.)
> 
>     The word EXPECT in this new feature should be changed to something else
>     to avoid confusion with the other KUnit concept.  Or alternately,
>     KUnit could change the word used for its existing concept, if that
>     is an easier change.
> 
A lot of test systems use "expected value" or terminology to that effect,
and compare that with "value seen" or "value received".  I didn't follow
this thread closely.  Does the test scan the logs looking for specific messages
to match against, to determine pass/fail criteria?  If so, then EXPECT
is OK in this context.  If it is being done afterwards by a human, then 
I think the marker should be called something else.
 -- Tim

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> 
> The issue of messages generated by the kernel being tested (that are not
> messages directly created by the tests, but are instead triggered as a
> side effect of the test) came up.  In this thread, I will call these
> messages "expected messages".  Instead of sidetracking that thread with
> a proposal to handle expected messages, I am starting this new thread.
> 
> I implemented an API for expected messages that are triggered by tests
> in the Devicetree unittest code, with the expectation that the specific
> details may change when the Devicetree unittest code adapts the KUnit
> API.  It seems appropriate to incorporate the concept of expected
> messages in Tim's documentation instead of waiting to address the
> subject when the Devicetree unittest code adapts the KUnit API, since
> Tim's document may become the kernel selftest standard.
> 
> Instead of creating a very long email containing multiple objects,
> I will reply to this email with a separate reply for each of:
> 
>   The "expected messages" API implemention and use can be from
>   drivers/of/unittest.c in the mainline kernel.
> 
>   of_unittest_expect - A proof of concept perl program to filter console
>                        output containing expected messages output
> 
>                        of_unittest_expect is also available by cloning
>                        https://github.com/frowand/dt_tools.git
> 
>   An example raw console output with timestamps and expect messages.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are not removed, but are flagged.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are removed instead of being flagged.
> 


# reply 2/5

#!/usr/bin/perl
# SPDX-License-Identifier: GPL-2.0
#
# Copyright 2020 Sony Corporation
#
# Author: Frank Rowand

# This program is meant to be an aid to reading the output of the Linux
# kernel devicetree unittest (drivers/of/unitest.c).  A design goal of
# unittest is that the output is directly usable without a helper program
# such as this one.

$VUFX = "200115a";


use strict 'refs';
use strict subs;

use Getopt::Long;
use Text::Wrap;


# strip off everything before final "/"
(undef, $script_name) = split(/^.*\//, $0);


#______________________________________________________________________________
sub compare {
	my ($expect, $got) = @_;
	my $expect_next;
	my $expect_next_lit;
	my $got_next;
	my $type;

	while ($expect) {

		($expect_next, $type) = split(/<</, $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:

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> 
> The issue of messages generated by the kernel being tested (that are not
> messages directly created by the tests, but are instead triggered as a
> side effect of the test) came up.  In this thread, I will call these
> messages "expected messages".  Instead of sidetracking that thread with
> a proposal to handle expected messages, I am starting this new thread.
> 
> I implemented an API for expected messages that are triggered by tests
> in the Devicetree unittest code, with the expectation that the specific
> details may change when the Devicetree unittest code adapts the KUnit
> API.  It seems appropriate to incorporate the concept of expected
> messages in Tim's documentation instead of waiting to address the
> subject when the Devicetree unittest code adapts the KUnit API, since
> Tim's document may become the kernel selftest standard.
> 
> Instead of creating a very long email containing multiple objects,
> I will reply to this email with a separate reply for each of:
> 
>   The "expected messages" API implemention and use can be from
>   drivers/of/unittest.c in the mainline kernel.
> 
>   of_unittest_expect - A proof of concept perl program to filter console
>                        output containing expected messages output
> 
>                        of_unittest_expect is also available by cloning
>                        https://github.com/frowand/dt_tools.git
> 
>   An example raw console output with timestamps and expect messages.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are not removed, but are flagged.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are removed instead of being flagged.
> 

reply 3/5

This is the raw console output for the Devicetree unittest.

Even with lines 1 - 205 deleted, this is pretty noisy and
difficult to read.

This test run shows one of the unittests failing (search for
the string "FAIL") and an associated expected console error
message is missing.


[    2.370062] s4: Bringing 0uV into 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
/ # 

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> 
> The issue of messages generated by the kernel being tested (that are not
> messages directly created by the tests, but are instead triggered as a
> side effect of the test) came up.  In this thread, I will call these
> messages "expected messages".  Instead of sidetracking that thread with
> a proposal to handle expected messages, I am starting this new thread.
> 
> I implemented an API for expected messages that are triggered by tests
> in the Devicetree unittest code, with the expectation that the specific
> details may change when the Devicetree unittest code adapts the KUnit
> API.  It seems appropriate to incorporate the concept of expected
> messages in Tim's documentation instead of waiting to address the
> subject when the Devicetree unittest code adapts the KUnit API, since
> Tim's document may become the kernel selftest standard.
> 
> Instead of creating a very long email containing multiple objects,
> I will reply to this email with a separate reply for each of:
> 
>   The "expected messages" API implemention and use can be from
>   drivers/of/unittest.c in the mainline kernel.
> 
>   of_unittest_expect - A proof of concept perl program to filter console
>                        output containing expected messages output
> 
>                        of_unittest_expect is also available by cloning
>                        https://github.com/frowand/dt_tools.git
> 
>   An example raw console output with timestamps and expect messages.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are not removed, but are flagged.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are removed instead of being flagged.
> 

reply 4/5

This is the previous raw console output for the Devicetree unittest,
filtered by of_unittest_expect.  The expected messages are not
eliminated, but are flagged with "ok" in the leading columns.

Lines 1 - 205 deleted again.

This test run shows one of the unittests failing (search for
the string "FAIL") and an associated expected console error
message is missing.

  EXPECT begin and EXPECT end lines are suppressed.
  Lines that match an EXPECT line are flagged with a leading 'ok'.
  Lines reporting a of_unittest_expect warning or error are flagged
     with a leading '**'.
  Lines reporting start or end of the unittests are flagged
     with a leading '->'.
  Lines reporting a unittest test FAIL are flagged
     with a leading '>>'.


   s4: Bringing 0uV into 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
   / # 

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> 
> The issue of messages generated by the kernel being tested (that are not
> messages directly created by the tests, but are instead triggered as a
> side effect of the test) came up.  In this thread, I will call these
> messages "expected messages".  Instead of sidetracking that thread with
> a proposal to handle expected messages, I am starting this new thread.
> 
> I implemented an API for expected messages that are triggered by tests
> in the Devicetree unittest code, with the expectation that the specific
> details may change when the Devicetree unittest code adapts the KUnit
> API.  It seems appropriate to incorporate the concept of expected
> messages in Tim's documentation instead of waiting to address the
> subject when the Devicetree unittest code adapts the KUnit API, since
> Tim's document may become the kernel selftest standard.
> 
> Instead of creating a very long email containing multiple objects,
> I will reply to this email with a separate reply for each of:
> 
>   The "expected messages" API implemention and use can be from
>   drivers/of/unittest.c in the mainline kernel.
> 
>   of_unittest_expect - A proof of concept perl program to filter console
>                        output containing expected messages output
> 
>                        of_unittest_expect is also available by cloning
>                        https://github.com/frowand/dt_tools.git
> 
>   An example raw console output with timestamps and expect messages.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are not removed, but are flagged.
> 
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are removed instead of being flagged.
> 

reply 5/5

This is the previous raw console output for the Devicetree unittest,
filtered by of_unittest_expect.  The expected messages are eliminated
instead of being flagged.

Lines 1 - 205 deleted again.

The output is still somewhat noisy because the Devicetree unittest
is running in parallel with some unrelated driver initialization.

This test run shows one of the unittests failing (search for
the string "FAIL") and an associated expected console error
message is missing.

  EXPECT begin and EXPECT end lines are suppressed.
  Lines that match an EXPECT line are suppressed.
  Lines reporting a of_unittest_expect warning or error are flagged
     with a leading '**'.
  Lines reporting start or end of the unittests are flagged
     with a leading '->'.
  Lines reporting a unittest test FAIL are flagged
     with a leading '>>'.


   s4: supplied by regulator-dummy
   s4: Bringing 0uV into 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
   / # 

Re: RFC: KTAP documentation - expected messages

[David Gow]

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@CY4PR13MB1175.namprd13.prod.outlook.com
>
> The issue of messages generated by the kernel being tested (that are not
> messages directly created by the tests, but are instead triggered as a
> side effect of the test) came up.  In this thread, I will call these
> messages "expected messages".  Instead of sidetracking that thread with
> a proposal to handle expected messages, I am starting this new thread.

Thanks for doing this: I think there are quite a few tests which could
benefit from something like this.

I think there were actually two separate questions: what do we do with
unexpected messages (most of which I expect are useless, but some of
which may end up being related to an unexpected test failure), and how
to have tests "expect" a particular message to appear. I'll stick to
talking about the latter for this thread, but even there there's two
possible interpretations of "expected messages" we probably want to
explicitly distinguish between: a message which must be present for
the test to pass (which I think best fits the "expected message"
name), and a message which the test is likely to produce, but which
shouldn't alter the result (an "ignored message"). I don't see much
use for the latter at present, but if we wanted to do more things with
messages and had some otherwise very verbose tests, it could
potentially be useful.

The other thing I'd note here is that this proposal seems to be doing
all of the actual message filtering in userspace, which makes a lot of
sense for kselftest tests, but does mean that the kernel can't know if
the test has passed or failed. There's definitely a tradeoff between
trying to put too much needless string parsing in the kernel and
having to have a userland tool determine the test results. The
proposed KCSAN test suite[1] is using tracepoints to do this in the
kernel. It's not the cleanest thing, but there's no reason KUnit or
similar couldn't implement a nicer API around it.

[1]: https://lkml.org/lkml/2020/6/22/1506

> I implemented an API for expected messages that are triggered by tests
> in the Devicetree unittest code, with the expectation that the specific
> details may change when the Devicetree unittest code adapts the KUnit
> API.  It seems appropriate to incorporate the concept of expected
> messages in Tim's documentation instead of waiting to address the
> subject when the Devicetree unittest code adapts the KUnit API, since
> Tim's document may become the kernel selftest standard.

Is having a nice way to handle expected messages the only thing
holding up porting this to KUnit?

> Instead of creating a very long email containing multiple objects,
> I will reply to this email with a separate reply for each of:
>
>   The "expected messages" API implemention and use can be from
>   drivers/of/unittest.c in the mainline kernel.
>
>   of_unittest_expect - A proof of concept perl program to filter console
>                        output containing expected messages output
>
>                        of_unittest_expect is also available by cloning
>                        https://github.com/frowand/dt_tools.git
>
>   An example raw console output with timestamps and expect messages.
>
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are not removed, but are flagged.
>
>   An example of console output processed by filter program
>   of_unittest_expect to be more human readable.  The expected
>   messages are removed instead of being flagged.

Cheers,
-- David

Re: RFC: KTAP documentation - expected messages

[Brendan Higgins]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> >
> > The issue of messages generated by the kernel being tested (that are not
> > messages directly created by the tests, but are instead triggered as a
> > side effect of the test) came up.  In this thread, I will call these
> > messages "expected messages".  Instead of sidetracking that thread with
> > a proposal to handle expected messages, I am starting this new thread.
>
> Thanks for doing this: I think there are quite a few tests which could
> benefit from something like this.
>
> I think there were actually two separate questions: what do we do with
> unexpected messages (most of which I expect are useless, but some of
> which may end up being related to an unexpected test failure), and how
> to have tests "expect" a particular message to appear. I'll stick to
> talking about the latter for this thread, but even there there's two
> possible interpretations of "expected messages" we probably want to
> explicitly distinguish between: a message which must be present for
> the test to pass (which I think best fits the "expected message"
> name), and a message which the test is likely to produce, but which
> shouldn't alter the result (an "ignored message"). I don't see much
> use for the latter at present, but if we wanted to do more things with
> messages and had some otherwise very verbose tests, it could
> potentially be useful.

+Dmitry Vyukov, I think you were interested in this for KASAN before
we went with the signalling approach. Any thoughts?

> The other thing I'd note here is that this proposal seems to be doing
> all of the actual message filtering in userspace, which makes a lot of
> sense for kselftest tests, but does mean that the kernel can't know if
> the test has passed or failed. There's definitely a tradeoff between
> trying to put too much needless string parsing in the kernel and
> having to have a userland tool determine the test results. The
> proposed KCSAN test suite[1] is using tracepoints to do this in the
> kernel. It's not the cleanest thing, but there's no reason KUnit or
> similar couldn't implement a nicer API around it.
>
> [1]: https://lkml.org/lkml/2020/6/22/1506
>
> > I implemented an API for expected messages that are triggered by tests
> > in the Devicetree unittest code, with the expectation that the specific
> > details may change when the Devicetree unittest code adapts the KUnit
> > API.  It seems appropriate to incorporate the concept of expected
> > messages in Tim's documentation instead of waiting to address the
> > subject when the Devicetree unittest code adapts the KUnit API, since
> > Tim's document may become the kernel selftest standard.
>
> Is having a nice way to handle expected messages the only thing
> holding up porting this to KUnit?
>
> > Instead of creating a very long email containing multiple objects,
> > I will reply to this email with a separate reply for each of:
> >
> >   The "expected messages" API implemention and use can be from
> >   drivers/of/unittest.c in the mainline kernel.
> >
> >   of_unittest_expect - A proof of concept perl program to filter console
> >                        output containing expected messages output
> >
> >                        of_unittest_expect is also available by cloning
> >                        https://github.com/frowand/dt_tools.git
> >
> >   An example raw console output with timestamps and expect messages.
> >
> >   An example of console output processed by filter program
> >   of_unittest_expect to be more human readable.  The expected
> >   messages are not removed, but are flagged.
> >
> >   An example of console output processed by filter program
> >   of_unittest_expect to be more human readable.  The expected
> >   messages are removed instead of being flagged.
>
> Cheers,
> -- David

Re: RFC: KTAP documentation - expected messages

[Frank Rowand]

+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@CY4PR13MB1175.namprd13.prod.outlook.com
>>
>> The issue of messages generated by the kernel being tested (that are not
>> messages directly created by the tests, but are instead triggered as a
>> side effect of the test) came up.  In this thread, I will call these
>> messages "expected messages".  Instead of sidetracking that thread with
>> a proposal to handle expected messages, I am starting this new thread.
> 
> Thanks for doing this: I think there are quite a few tests which could
> benefit from something like this.
> 
> I think there were actually two separate questions: what do we do with
> unexpected messages (most of which I expect are useless, but some of
> which may end up being related to an unexpected test failure), and how
> to have tests "expect" a particular message to appear. I'll stick to

Yes.  But there is also a third aspect that made this feature important
for the Devicetree unittest.  There was a question on the devicetree
mail list, asking whether some devicetree related kernel warning and/or
error messages were devicetree problems.  The messages appeared while
the unittest was executing, but at the same time a lot of system
initialization is in progress, resulting in lots of console messages
that are unrelated to unittest.  I could not in good conscious reply
that the messages were truly of no consequence without actually
chasing each of them down and verifying that they were triggered by
unittest, and were showing what the devicetree infrastructure should
be reporting in response to the test stimulus, vs an underlying bug
in the devicetree infrastructure.

I found the expected messages API to be a useful tool to document
the validity of the messages, both for myself, and for the random
developer who might be reading the boot messages.

> talking about the latter for this thread, but even there there's two
> possible interpretations of "expected messages" we probably want to
> explicitly distinguish between: a message which must be present for
> the test to pass (which I think best fits the "expected message"
> name), and a message which the test is likely to produce, but which
> shouldn't alter the result (an "ignored message").

This type of case was the impetus for me to create the API.  There
was a unittest that resulted in the probe of a device, where the
probe executed devicetree subsystem code that invoked a
blocking_notifier_call_chain(), that resulted in another subsystem
taking some action, and that action just happened to do a printk()
reporting a specific action that the unittest was trying to
verify.

I was able to verify much of the asynchronous activity by creating
a fake driver and corresponding devices to be probed and could
instrument the fake driver.  The printk() information provided
the last little bit of checking for correct behavior.

> I don't see much
> use for the latter at present, but if we wanted to do more things with
> messages and had some otherwise very verbose tests, it could
> potentially be useful.

The use for the "ignored message" is my third aspect above.  This points
out that yet another possible consumer of the console boot log is the
QA or test engineer.  They can have the same concerns as any "random
developer".

> 
> The other thing I'd note here is that this proposal seems to be doing
> all of the actual message filtering in userspace, which makes a lot of
> sense for kselftest tests, but does mean that the kernel can't know if
> the test has passed or failed.

Yes.  I had absolutely no interest in my test code examining the history
of console messages, which could be generated on any other processor.

The printk related code has always been complex, nuanced, and seems to
attract the attention of people who want to change it instead of
leaving it stable.  I would really like to stay away from any dependency
on it.

> There's definitely a tradeoff between
> trying to put too much needless string parsing in the kernel and
> having to have a userland tool determine the test results. The
> proposed KCSAN test suite[1] is using tracepoints to do this in the
> kernel. It's not the cleanest thing, but there's no reason KUnit or
> similar couldn't implement a nicer API around it.

My interest is in printk() based messages that are present in areas
outside of my test code and independent of my test code.  I specifically
did not want to modify that existing code with any test code.

I was willing to accept the extra layer of running a user space program
to process the console output to verify one small portion of the
test passing or failing (or alternately, just examining the console
output manually).

-Frank

> 
> [1]: https://lkml.org/lkml/2020/6/22/1506
> 
>> I implemented an API for expected messages that are triggered by tests
>> in the Devicetree unittest code, with the expectation that the specific
>> details may change when the Devicetree unittest code adapts the KUnit
>> API.  It seems appropriate to incorporate the concept of expected
>> messages in Tim's documentation instead of waiting to address the
>> subject when the Devicetree unittest code adapts the KUnit API, since
>> Tim's document may become the kernel selftest standard.
> 
> Is having a nice way to handle expected messages the only thing
> holding up porting this to KUnit?
> 
>> Instead of creating a very long email containing multiple objects,
>> I will reply to this email with a separate reply for each of:
>>
>>   The "expected messages" API implemention and use can be from
>>   drivers/of/unittest.c in the mainline kernel.
>>
>>   of_unittest_expect - A proof of concept perl program to filter console
>>                        output containing expected messages output
>>
>>                        of_unittest_expect is also available by cloning
>>                        https://github.com/frowand/dt_tools.git
>>
>>   An example raw console output with timestamps and expect messages.
>>
>>   An example of console output processed by filter program
>>   of_unittest_expect to be more human readable.  The expected
>>   messages are not removed, but are flagged.
>>
>>   An example of console output processed by filter program
>>   of_unittest_expect to be more human readable.  The expected
>>   messages are removed instead of being flagged.
> 
> Cheers,
> -- David
> 

Re: RFC: KTAP documentation - expected messages

[Alan Maguire]

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@CY4PR13MB1175.namprd13.prod.outlook.com
> >
> > The issue of messages generated by the kernel being tested (that are not
> > messages directly created by the tests, but are instead triggered as a
> > side effect of the test) came up.  In this thread, I will call these
> > messages "expected messages".  Instead of sidetracking that thread with
> > a proposal to handle expected messages, I am starting this new thread.
> 
> Thanks for doing this: I think there are quite a few tests which could
> benefit from something like this.
> 
> I think there were actually two separate questions: what do we do with
> unexpected messages (most of which I expect are useless, but some of
> which may end up being related to an unexpected test failure), and how
> to have tests "expect" a particular message to appear. I'll stick to
> talking about the latter for this thread, but even there there's two
> possible interpretations of "expected messages" we probably want to
> explicitly distinguish between: a message which must be present for
> the test to pass (which I think best fits the "expected message"
> name), and a message which the test is likely to produce, but which
> shouldn't alter the result (an "ignored message"). I don't see much
> use for the latter at present, but if we wanted to do more things with
> messages and had some otherwise very verbose tests, it could
> potentially be useful.
> 
> The other thing I'd note here is that this proposal seems to be doing
> all of the actual message filtering in userspace, which makes a lot of
> sense for kselftest tests, but does mean that the kernel can't know if
> the test has passed or failed. There's definitely a tradeoff between
> trying to put too much needless string parsing in the kernel and
> having to have a userland tool determine the test results. The
> proposed KCSAN test suite[1] is using tracepoints to do this in the
> kernel. It's not the cleanest thing, but there's no reason KUnit or
> similar couldn't implement a nicer API around it.
> 
> [1]: https://lkml.org/lkml/2020/6/22/1506
>

For KTF the way we handled this was to use the APIs for catching
function entry and return (via kprobes), specifying printk as the
function to catch, and checking its argument string to verify
the expected message was seen. That allows you to verify
that messages appear in kernel testing context, but it's
not ideal as printk() has not yet filled in the arguments in
the buffer for display (there may be a better place to trace).
If it seems like it could be useful I  could have a go at 
porting the kprobe stuff to KUnit, as it helps expand the vocabulary 
for what can be tested in kernel context; for example we can 
also override return values for kernel functions to simulate errors.

Alan