MIME-Version: 1.0
References: <20230222182740.254087-1-rmoar@google.com> <20230222182740.254087-3-rmoar@google.com>
 <CABVgOSmJRxCT=NZ7ZWMwCrpHJHnHBAa=XmuNcLAJd_FrBvMZBw@mail.gmail.com>
In-Reply-To: <CABVgOSmJRxCT=NZ7ZWMwCrpHJHnHBAa=XmuNcLAJd_FrBvMZBw@mail.gmail.com>
From:   Rae Moar <rmoar@google.com>
Date:   Thu, 23 Feb 2023 16:45:07 -0500
Message-ID: <CA+GJov6cGOu0+F=N9qvv2NTCro7YhHZJxi1UuJCCus9a17yH=g@mail.gmail.com>
Subject: Re: [PATCH v2 3/3] kunit: fix bug of extra newline characters 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"
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

On Thu, Feb 23, 2023 at 12:51 AM David Gow <davidgow@google.com> wrote:
>
> On Thu, 23 Feb 2023 at 02:27, Rae Moar <rmoar@google.com> 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 app=
ears
> > in the debugfs log.
> >
> > This is due to a discrepancy between how the lines are printed and how =
they
> > are added to the logs. Remove this discrepancy by checking if the a new=
line
>
> Nit: "if the a"?

Thanks for catching this. I will change this to "if a."

>
> > character is present before adding a newline character to the log. This
> > should closely match the printk behavior.
> >
> > Add kunit_log_newline_test to provide test coverage for this issue. (Al=
so,
> > move kunit_log_test above suite definition to remove the unnecessary
> > declaration prior to the suite definition)
> >
> > As an example, say we add these two lines to the log:
> >
> > kunit_log(..., =E2=80=9CKTAP version 1\n=E2=80=9D);
> > kunit_log(..., =E2=80=9C1..1=E2=80=9D);
>
> Nit: Please use regular quotes here ("), rather than the "smart quotes" (=
=E2=80=9C=E2=80=9D).

Oops. Thanks. I will change these quotes.

>
> >
> > The debugfs log before this fix:
> >
> >  KTAP version 1
> >
> >  1..1
> >
> > The debugfs log after this fix:
> >
> >  KTAP version 1
> >  1..1
> >
> > Signed-off-by: Rae Moar <rmoar@google.com>
> > ---
> >
> This overall seems better. I haven't finished reviewing the series
> yet, but there are a few obvious issues with this patch still...
>
> Most notably, kunit-log-test.kunit_log_test now fails.
>
> -- David
>
> > Changes from v1 -> v2:
> > - Changed the way extra newlines are removed. Instead of removing extra
> >   newline characters, add a newline if one is not present. This is a bi=
t
> >   cleaner.
> > - Add before and after results to the commit message.
> > - Note: I looked into using KERN_CONT to match the printk behavior to
> >   vsnprintf but this could cause issues with KTAP printing on the same =
line
> >   as interrupting kernel messages. I also looked at adding KERN_CONT
> >   functionality to kunit_log and I did get this to work but it was a bi=
t
> >   messy because it required a few calls to kunit_log_newline in
> >   kunit_run_tests. If this is very desired functionality, happy to add =
this
> >   to version 3.
> >
> >  include/kunit/test.h   |  9 ++++++++-
> >  lib/kunit/kunit-test.c | 35 +++++++++++++++++++++++------------
> >  lib/kunit/test.c       | 14 ++++++++++++++
> >  3 files changed, 45 insertions(+), 13 deletions(-)
> >
> > diff --git a/include/kunit/test.h b/include/kunit/test.h
> > index 0668d29f3453..3031ad29718b 100644
> > --- a/include/kunit/test.h
> > +++ b/include/kunit/test.h
> > @@ -375,6 +375,13 @@ static inline void *kunit_kcalloc(struct kunit *te=
st, size_t n, size_t size, gfp
> >
> >  void kunit_cleanup(struct kunit *test);
> >
> > +/**
> > + * kunit_log_newline() - Add newline to the end of log if not already
> > + * present at the end of the log.
> > + * @log: The log to add the newline to.
> > + */
> > +void kunit_log_newline(char *log);
> > +
>
> I don't think this function needs to be public. Maybe keep it static
> and internal to test.c?

Changing this to static makes sense. I will update this.

>
> >  void __printf(2, 3) kunit_log_append(char *log, const char *fmt, ...);
> >
> >  /**
> > @@ -420,7 +427,7 @@ void __printf(2, 3) kunit_log_append(char *log, con=
st char *fmt, ...);
> >  #define kunit_log(lvl, test_or_suite, fmt, ...)                       =
         \
> >         do {                                                           =
 \
> >                 printk(lvl fmt, ##__VA_ARGS__);                        =
 \
> > -               kunit_log_append((test_or_suite)->log,  fmt "\n",      =
 \
> > +               kunit_log_append((test_or_suite)->log,  fmt,    \
> >                                  ##__VA_ARGS__);                       =
 \
> >         } while (0)
> >
> > diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> > index 4df0335d0d06..b63595d3e241 100644
> > --- a/lib/kunit/kunit-test.c
> > +++ b/lib/kunit/kunit-test.c
> > @@ -443,18 +443,6 @@ static struct kunit_suite kunit_resource_test_suit=
e =3D {
> >         .test_cases =3D kunit_resource_test_cases,
> >  };
> >
> > -static void kunit_log_test(struct kunit *test);
> > -
> > -static struct kunit_case kunit_log_test_cases[] =3D {
> > -       KUNIT_CASE(kunit_log_test),
> > -       {}
> > -};
> > -
> > -static struct kunit_suite kunit_log_test_suite =3D {
> > -       .name =3D "kunit-log-test",
> > -       .test_cases =3D kunit_log_test_cases,
> > -};
> > -
> >  static void kunit_log_test(struct kunit *test)
> >  {
> >         struct kunit_suite suite;
> > @@ -481,6 +469,29 @@ static void kunit_log_test(struct kunit *test)
> >  #endif
> >  }
> >
> > +static void kunit_log_newline_test(struct kunit *test)
> > +{
> > +       kunit_info(test, "Add newline\n");
> > +       if (test->log) {
> > +               KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(test->log, "Add =
newline\n"),
> > +                       "Missing log line, full log:\n%s", test->log);
> > +               KUNIT_EXPECT_NULL(test, strstr(test->log, "Add newline\=
n\n"));
> > +       } else {
> > +               kunit_skip(test, "only useful when debugfs is enabled")=
;
> > +       }
> > +}
> > +
> > +static struct kunit_case kunit_log_test_cases[] =3D {
> > +       KUNIT_CASE(kunit_log_test),
>
> This test is failing now:
> [13:42:51] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D kunit-log-test (=
2 subtests) =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> [13:42:51] put this in log.
> [13:42:51] this too.
> [13:42:51] add to suite log.
> [13:42:51] along with this.
> [13:42:51]     # kunit_log_test: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:459
> [13:42:51]     Expected strstr(test->log, "put this in log.") is not
> null, but is
> [13:42:51]     # kunit_log_test: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:461
> [13:42:51]     Expected strstr(test->log, "this too.") is not null, but i=
s
> [13:42:51]     # kunit_log_test: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:463
> [13:42:51]     Expected strstr(suite.log, "add to suite log.") is not
> null, but is
> [13:42:51]     # kunit_log_test: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:465
> [13:42:51]     Expected strstr(suite.log, "along with this.") is not
> null, but is
> [13:42:51] [FAILED] kunit_log_test
> [13:42:51] [PASSED] kunit_log_newline_test
> [13:42:51] # kunit-log-test: pass:1 fail:1 skip:0 total:2
> [13:42:51] # Totals: pass:1 fail:1 skip:0 total:2
> [13:42:51] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D [FAILED] k=
unit-log-test =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>

Sorry I did not catch this earlier. I must have tested on an outdated
version of my code. The fix here is I am missing a "+ 1" in
kunit_log_append(). This fix is for the first patch in this series and
the specific line change is:

- len =3D vsnprintf(NULL, 0, fmt, args);
+ len =3D vsnprintf(NULL, 0, fmt, args) + 1;

I will update this in the next version.

> > +       KUNIT_CASE(kunit_log_newline_test),
> > +       {}
> > +};
> > +
> > +static struct kunit_suite kunit_log_test_suite =3D {
> > +       .name =3D "kunit-log-test",
> > +       .test_cases =3D 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 fb6b39cca0ae..1ea981392af3 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -108,6 +108,17 @@ static void kunit_print_test_stats(struct kunit *t=
est,
> >                   stats.total);
> >  }
> >
> > +void kunit_log_newline(char *log)
> > +{
> > +       int log_len, len_left;
> > +
> > +       log_len =3D strlen(log);
> > +       len_left =3D KUNIT_LOG_SIZE - log_len - 1;
> > +
> > +       if (log_len > 0 && log[log_len - 1] !=3D '\n')
> > +               strncat(log, "\n", len_left);
> > +}
> > +
> >  /*
> >   * Append formatted message to log, size of which is limited to
> >   * KUNIT_LOG_SIZE bytes (including null terminating byte).
> > @@ -134,6 +145,9 @@ void kunit_log_append(char *log, const char *fmt, .=
..)
> >         va_start(args, fmt);
> >         vsnprintf(log + log_len, min(len, len_left), fmt, args);
> >         va_end(args);
> > +
> > +       /* Add newline to end of log if not already present. */
> > +       kunit_log_newline(log);
> >  }
> >  EXPORT_SYMBOL_GPL(kunit_log_append);
> >
> > --
> > 2.39.2.637.g21b0678d19-goog
> >