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

[David Gow]

On Wed, 1 Feb 2023 at 06:04, Rae Moar <rmoar@xxxxxxxxxx> 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@xxxxxxxxxx>
> ---

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

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

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

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
>

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature