MIME-Version: 1.0
References: <20230131220355.1603527-1-rmoar@google.com> <20230131220355.1603527-3-rmoar@google.com>
 <CABVgOSk_jWzywAKASy1U2mQOC=SM_TDt753VyF1hUtwWzoszPw@mail.gmail.com>
In-Reply-To: <CABVgOSk_jWzywAKASy1U2mQOC=SM_TDt753VyF1hUtwWzoszPw@mail.gmail.com>
From:   Rae Moar <rmoar@google.com>
Date:   Fri, 10 Feb 2023 14:28:44 -0500
Message-ID: <CA+GJov5OCM4VNZ4QsEEcH-V+S+sPoUN8B9b_stFD-r00RYF2hw@mail.gmail.com>
Subject: Re: [PATCH v1 2/3] kunit: fix bug in the order of lines in debugfs logs
To:     David Gow <davidgow@google.com>
Cc:     brendanhiggins@google.com, dlatypov@google.com,
        skhan@linuxfoundation.org, kunit-dev@googlegroups.com,
        linux-kernel@vger.kernel.org, linux-kselftest@vger.kernel.org
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

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