diff mbox series

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

Message ID 20230131220355.1603527-3-rmoar@google.com
State New
Headers show
Series kunit: fix bugs in debugfs logs | expand

Commit Message

Rae Moar Jan. 31, 2023, 10:03 p.m. UTC
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>
---
 lib/kunit/debugfs.c | 13 ++++++++-----
 lib/kunit/test.c    | 24 ++++++++++++------------
 2 files changed, 20 insertions(+), 17 deletions(-)

Comments

David Gow Feb. 9, 2023, 5:06 a.m. UTC | #1
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).

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
>
Rae Moar Feb. 10, 2023, 7:28 p.m. UTC | #2
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
> >
diff mbox series

Patch

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");
+	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);
+	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",
 			kunit_status_to_ok_not_ok(status),
 			test_number, description, directive_header,
 			(status == KUNIT_SKIPPED) ? directive : "");