Re: [PATCH v1 3/3] kunit: fix bug of extra newline characters in debugfs logs

[Rae Moar]

On Thu, Feb 9, 2023 at 12:06 AM David Gow <davidgow@xxxxxxxxxx> wrote:
>
> On Wed, 1 Feb 2023 at 06:04, Rae Moar <rmoar@xxxxxxxxxx> wrote:
> >
> > Fix bug of the extra newline characters in debugfs logs. When a
> > line is added to debugfs with a newline character at the end,
> > an extra line appears in the debugfs log. Remove these extra lines.
> >
> > Add kunit_log_newline_test to provide test coverage for this issue.
> > (Also, move kunit_log_test above suite definition to remove the
> > unnecessary declaration prior to the suite definition)
> >
> > Signed-off-by: Rae Moar <rmoar@xxxxxxxxxx>
> > ---

Hi David!

>
> I've got some reservations about this patch.
>
> Firstly, could we have an example of the problem in the commit
> message, so we know what we're fixing?

Yes, as mentioned in the second patch, I will add an individual
"before and after" comparison to each of the patches in v2. This is
much clearer than just the overall comparison in the cover letter.

>
> Secondly, I _really_ don't like the way this just removes newlines
> from log lines if there are too many. It feels like a hack, rather
> than a proper fix.
>
> I suspect the actual issue here is in the kunit_log macro in
> include/kunit/test.h:
> https://elixir.bootlin.com/linux/latest/source/include/kunit/test.h#L417
>
> kunit_log_append((test_or_suite)->log, fmt "\n", ##__VA_ARGS__); \
>
> The "\n" concatenated here is probably the issue. The printk statement
> doesn't add a newline, but that's because printk implicitly does if
> KERN_CONT is not added.
>
> So maybe the correct fix here is to use:
> printk(KERN_CONT lvl fmt "\n", ##__VA_ARGS__)
>
> That'd add the newline, rather than get rid of it, but at least should
> make the behaviour more similar between printk and the debugfs log.
> Equally, you could use KERN_CONT and get rid of the "\n" in both
> places, requiring it in log messages.

I understand how this seems a bit hacky. There were quite a few
discussions on how to approach this prior to sending this out on this
list. But changing the printk to be consistent between the debugfs and
normal output is a great idea! This does cause a few tests to have
extra lines in the output but shouldn't cause any issues with the
parser readable output. I will definitely change this in v2.

>
> Thirdly, I don't really like the way the test is skipped if debugfs
> isn't active. Could we skip it if test->log is not valid instead or
> using a compile-time #ifdef?

Yes this makes sense. Happy to change this in v2. The kunit_log_test
also uses this #ifdef statement. Should this be changed as well?

>
> I do like the move of kunit_log_test though. That definitely cleans things up!
>
> Cheers,
> -- David
>

Thanks!

Rae

>
> >  lib/kunit/kunit-test.c | 36 ++++++++++++++++++++++++------------
> >  lib/kunit/test.c       |  9 ++++++++-
> >  2 files changed, 32 insertions(+), 13 deletions(-)
> >
> > diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> > index 4df0335d0d06..e9114a466f1e 100644
> > --- a/lib/kunit/kunit-test.c
> > +++ b/lib/kunit/kunit-test.c
> > @@ -443,18 +443,6 @@ static struct kunit_suite kunit_resource_test_suite = {
> >         .test_cases = kunit_resource_test_cases,
> >  };
> >
> > -static void kunit_log_test(struct kunit *test);
> > -
> > -static struct kunit_case kunit_log_test_cases[] = {
> > -       KUNIT_CASE(kunit_log_test),
> > -       {}
> > -};
> > -
> > -static struct kunit_suite kunit_log_test_suite = {
> > -       .name = "kunit-log-test",
> > -       .test_cases = kunit_log_test_cases,
> > -};
> > -
> >  static void kunit_log_test(struct kunit *test)
> >  {
> >         struct kunit_suite suite;
> > @@ -481,6 +469,30 @@ static void kunit_log_test(struct kunit *test)
> >  #endif
> >  }
> >
> > +static void kunit_log_newline_test(struct kunit *test)
> > +{
> > +#ifdef CONFIG_KUNIT_DEBUGFS
> > +       kunit_info(test, "extra newline\n");
> > +
> > +       KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(test->log, "extra newline\n"),
> > +               "Missing log line, full log:\n%s", test->log);
> > +       KUNIT_EXPECT_NULL(test, strstr(test->log, "extra newline\n\n"));
> > +#else
> > +       kunit_skip(test, "only useful when debugfs is enabled");
> > +#endif
> > +}
> > +
> > +static struct kunit_case kunit_log_test_cases[] = {
> > +       KUNIT_CASE(kunit_log_test),
> > +       KUNIT_CASE(kunit_log_newline_test),
> > +       {}
> > +};
> > +
> > +static struct kunit_suite kunit_log_test_suite = {
> > +       .name = "kunit-log-test",
> > +       .test_cases = kunit_log_test_cases,
> > +};
> > +
> >  static void kunit_status_set_failure_test(struct kunit *test)
> >  {
> >         struct kunit fake;
> > diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> > index 27763f0b420c..76d9c31943bf 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -117,6 +117,7 @@ void kunit_log_append(char *log, const char *fmt, ...)
> >         char line[KUNIT_LOG_SIZE];
> >         va_list args;
> >         int len_left;
> > +       int line_len;
> >
> >         if (!log)
> >                 return;
> > @@ -125,10 +126,16 @@ void kunit_log_append(char *log, const char *fmt, ...)
> >         if (len_left <= 0)
> >                 return;
> >
> > +       // Evaluate the length of the line with arguments
> >         va_start(args, fmt);
> > -       vsnprintf(line, sizeof(line), fmt, args);
> > +       line_len = vsnprintf(line, sizeof(line), fmt, args);
> >         va_end(args);
> >
> > +       // If line has two newline characters, do not print
> > +       // second newline character
> > +       if (fmt[strlen(fmt) - 2] == '\n')
> > +               line[line_len - 1] = '\0';
> > +
> >         strncat(log, line, len_left);
> >  }
> >  EXPORT_SYMBOL_GPL(kunit_log_append);
> > --
> > 2.39.1.456.gfc5497dd1b-goog
> >