Re: [PATCH v1 2/3] kunit: fix bug in the order of lines in debugfs logs

On Thu, Feb 9, 2023 at 12:06 AM David Gow davidgow@google.com wrote:

On Wed, 1 Feb 2023 at 06:04, Rae Moar rmoar@google.com wrote:

...

Fix bug in debugfs logs that causes an incorrect order of lines in the debugfs log.

Currently, any suite diagnostic lines, including the test counts lines that show the number of tests passed, failed, and skipped, appear prior to the individual results, which is a bug.

Ensure the order of printing for the debugfs log is correct.

Signed-off-by: Rae Moar rmoar@google.com

I think this is overall an improvement, but there are a few remaining issues (some new, some old).

Hi David!

Thanks for your comments.

First, as with the previous patches, could we have a before/after comparison in the commit description?

Yes, this sounds like a great idea. I originally thought the before and after comparison in the cover letter would be sufficient but an individual comparison for each patch is clearer. I will add this in v2.

Secondly, I think it'd be nice to either add an extra KTAP header to the start, so that each debugfs results file is a valid KTAP document by itself, or at least document that you'll need to prepend one for this to work. I'm personally leaning towards the latter, even if it loses us the ability to just concatenate result files together, because of the third issue below.

Finally, with this patch, the final result line's suite number is recorded from its initial run, rather than always being '1'. This means that if multiple suites are run (e.g. list-test.ko), then the result file could contain a single suite, with "ok 2 ..." or similar as a result line. This might help a bit if we were concatenating result files, but otherwise leaves us with a parse error due to the mismatched number.

Personally, I'd prefer we change those to always use suite number 1, and to add the KTAP header to the start. Adding the header should be easy, the suite number perhaps less so...

My intention was to match the logs with the exact KTAP output of the test to be consistent. But I see the value in ensuring the logs are easily parsable. In v2, I will add the KTAP header and change the test number to be 1 to allow the logs to be parsed without error.

-Rae

Cheers, -- David

...

lib/kunit/debugfs.c | 13 ++++++++----- lib/kunit/test.c | 24 ++++++++++++------------ 2 files changed, 20 insertions(+), 17 deletions(-)

diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c index de0ee2e03ed6..fbc645590701 100644 --- a/lib/kunit/debugfs.c +++ b/lib/kunit/debugfs.c @@ -52,19 +52,22 @@ static void debugfs_print_result(struct seq_file *seq, static int debugfs_print_results(struct seq_file *seq, void *v) { struct kunit_suite *suite = (struct kunit_suite *)seq->private;

•   enum kunit_status success = kunit_suite_has_succeeded(suite);
    struct kunit_case *test_case;
  
  

•   if (!suite || !suite->log)
  

•   if (!suite)
            return 0;
  
  

•   seq_printf(seq, "%s", suite->log);
  

•   /* Print suite header because it is not stored in the test logs. */
  

•   seq_puts(seq, KUNIT_SUBTEST_INDENT "KTAP version 1\n");
  

We probably want to print this twice, once without the indent, to start the whole document, once with it.

...

•   seq_printf(seq, KUNIT_SUBTEST_INDENT "# Subtest: %s\n", suite->name);
  

•   seq_printf(seq, KUNIT_SUBTEST_INDENT "1..%zd\n", kunit_suite_num_test_cases(suite));
  
    kunit_suite_for_each_test_case(suite, test_case)
            debugfs_print_result(seq, suite, test_case);
  
  

•   seq_printf(seq, "%s %d %s\n",
  

•              kunit_status_to_ok_not_ok(success), 1, suite->name);
  

We probably still want to output the suite number as '1'...

...

•   if (suite->log)
  

•           seq_printf(seq, "%s", suite->log);
  

•   return 0;
  

}

diff --git a/lib/kunit/test.c b/lib/kunit/test.c index 66ba93b8222c..27763f0b420c 100644 --- a/lib/kunit/test.c +++ b/lib/kunit/test.c @@ -147,10 +147,18 @@ EXPORT_SYMBOL_GPL(kunit_suite_num_test_cases);

static void kunit_print_suite_start(struct kunit_suite *suite) {

•   kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "KTAP version 1\n");
  

•   kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "# Subtest: %s",
  

•   /*
  

•    * We do not log the test suite header as doing so would
  

•    * mean debugfs display would consist of the test suite
  

•    * header prior to individual test results.
  

•    * Hence directly printk the suite status, and we will
  

•    * separately seq_printf() the suite header for the debugfs
  

•    * representation.
  

•    */
  

•   pr_info(KUNIT_SUBTEST_INDENT "KTAP version 1\n");
  

•   pr_info(KUNIT_SUBTEST_INDENT "# Subtest: %s",
              suite->name);
  

•   kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "1..%zd",
  

•   pr_info(KUNIT_SUBTEST_INDENT "1..%zd",
              kunit_suite_num_test_cases(suite));
  

}

@@ -165,16 +173,8 @@ static void kunit_print_ok_not_ok(void *test_or_suite, struct kunit *test = is_test ? test_or_suite : NULL; const char *directive_header = (status == KUNIT_SKIPPED) ? " # SKIP " : "";

•   /*
  

•    * We do not log the test suite results as doing so would
  

•    * mean debugfs display would consist of the test suite
  

•    * description and status prior to individual test results.
  

•    * Hence directly printk the suite status, and we will
  

•    * separately seq_printf() the suite status for the debugfs
  

•    * representation.
  

•    */
    if (suite)
  

•           pr_info("%s %zd %s%s%s\n",
  

•           kunit_log(KERN_INFO, suite, "%s %zd %s%s%s\n",
  

Changing this breaks the code to ensure the suite number is always '1'...

...

                    kunit_status_to_ok_not_ok(status),
                    test_number, description, directive_header,
                    (status == KUNIT_SKIPPED) ? directive : "");

-- 2.39.1.456.gfc5497dd1b-goog