mbox series

[v3,0/7] kunit: Add dynamically-extending log

Message ID 20230809155438.22470-1-rf@opensource.cirrus.com
Headers show
Series kunit: Add dynamically-extending log | expand

Message

Richard Fitzgerald Aug. 9, 2023, 3:54 p.m. UTC
Replace the original fixed-size log buffer with a dynamically-
extending log.

Patch 1 provides the basic implementation. The following patches
add test cases, support for logging long strings, and an optimization
to the string formatting that is now more thoroughly testable.

Changes since v2:
- Fixed uninitialized string bug in get_concatenated_log().
- Moved get_concatenated_log() into first patch so that
  kunit_log_newline_test() dumps the entire log on error.
- Moved kunit_log_frag_sized_line_test() to the correct point in
  the chain, after the change that it depends on. Also log another
  line after the long line to test that the log extends correctly.
- Added kunit_log_init_frag_test() to test kunit_init_log_frag()
  instead of testing it as part of every other test.

Richard Fitzgerald (7):
  kunit: Replace fixed-size log with dynamically-extending buffer
  kunit: kunit-test: Add test cases for extending log buffer
  kunit: Handle logging of lines longer than the fragment buffer size
  kunit: kunit-test: Test logging a line that exactly fills a fragment
  kunit: kunit-test: Add test cases for logging very long lines
  kunit: kunit-test: Add test of logging only a newline
  kunit: Don't waste first attempt to format string in
    kunit_log_append()

 include/kunit/test.h   |  25 ++-
 lib/kunit/debugfs.c    |  65 ++++++--
 lib/kunit/kunit-test.c | 339 ++++++++++++++++++++++++++++++++++++++++-
 lib/kunit/test.c       | 127 ++++++++++++---
 4 files changed, 507 insertions(+), 49 deletions(-)

Comments

Rae Moar Aug. 10, 2023, 10:41 p.m. UTC | #1
On Thu, Aug 10, 2023 at 9:38 AM David Gow <davidgow@google.com> wrote:
>
> On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
> >
> > Add handling to kunit_log_append() for log messages that are longer than
> > a single buffer fragment.
> >
> > The initial implementation of fragmented buffers did not change the logic
> > of the original kunit_log_append(). A consequence was that it still had
> > the original assumption that a log line will fit into one buffer.
> >
> > This patch checks for log messages that are larger than one fragment
> > buffer. In that case, kvasprintf() is used to format it into a temporary
> > buffer and that content is then split across as many fragments as
> > necessary.
> >
> > Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> > ---
>
> I think this looks good (and is a long-overdue addition to the logging
> functionality).
>
> One thought I have (and I'm kicking myself for not thinking of it
> earlier) is that this is starting to get very similar to the "string
> stream" functionality in lib/kunit/string-stream.{h,c}. Now, I
> actually think this implementation is much more efficient (using
> larger fragments, whereas the string stream uses variable-sized ones).
> Particularly since there are a lot of cases where string streams are
> created, converted to a string, and then logged, there's almost
> certainly a bunch of redundant work being done here.
>
> My gut feeling is that we should stick with this as-is, and maybe try
> to either work out some better integration between string streams and
> logging (to avoid that extra string allocation) or find some way of
> combining them.
>
> Regardless, this seems good as-is to me. There are some minor comments
> below, but nothing disastrous. I'll let Rae have a look over the
> various strscpy and strlcat calls, though, as while I did check them
> carefully (and KASAN hasn't complained), it's always best to have as
> many eyes on C string code as possible. :-)
>

Hello!

I have tested and taken a look at this and it looks overall good to
me. I think all of the string copying and concatenating is right.

Other than David's comments below, especially whether we should do
this with string-stream, I am pretty happy to accept this as is.

Thanks!
Rae

> But in my eyes, this is
> Reviewed-by: David Gow <davidgow@google.com>
>
> Cheers,
> -- David
>
> >  lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++---
> >  1 file changed, 61 insertions(+), 4 deletions(-)
> >
> > diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> > index dfe51bc2b387..28d0048d6171 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
> >         return frag;
> >  }
> >
> > +static void kunit_log_append_string(struct list_head *log, const char *src)
> > +{
> > +       struct kunit_log_frag *frag, *new_frag;
> > +       int log_len, bytes_left;
> > +       ssize_t written;
> > +       char *p;
> > +
> > +       frag = list_last_entry(log, struct kunit_log_frag, list);
> > +       log_len = strlen(frag->buf);
> > +       bytes_left = sizeof(frag->buf) - log_len;
> > +
> > +       written = strscpy(frag->buf + log_len, src, bytes_left);
> > +       if (written != -E2BIG)
> > +               goto newline;
> > +
> > +       src += bytes_left - 1;
> > +       do {
> > +               new_frag = kunit_log_extend(log);
> > +               if (!new_frag)
> > +                       goto newline;
> > +
> > +               frag = new_frag;
> > +               written = strscpy(frag->buf, src, sizeof(frag->buf));
> > +               src += sizeof(frag->buf) - 1;
> > +       } while (written == -E2BIG);
> > +
> > +newline:
> > +       if (written == -E2BIG)
>
> I think that this can only be true if kunit_log_extend() fails. If the
> do/while loop ends naturally, then written != -E2BIG, as is the case
> with the strscpy goto above.
>
> Do you think it's cleaner to move the 'written = strlen(frag->buf)
> into the if (!new_frag) statement within the loop?
>
> > +               written = strlen(frag->buf);
> > +
> > +       p = &frag->buf[written - 1];
> > +       if (*p != '\n') {
> > +               if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) {
> > +                       frag = kunit_log_extend(log);
> > +                       if (!frag) {
>
> A comment here could be useful. Something like "If we can't extend the
> log to add a newline, truncate the last message".
>
> > +                               *p = '\n';
> > +                               return;
> > +                       }
> > +
> > +                       frag->buf[0] = '\n';
> > +                       frag->buf[1] = '\0';
> > +               }
> > +       }
> > +}
> > +
> >  /* Append formatted message to log, extending the log buffer if necessary. */
> >  void kunit_log_append(struct list_head *log, const char *fmt, ...)
> >  {
> >         va_list args;
> >         struct kunit_log_frag *frag;
> >         int len, log_len, len_left;
> > +       char *tmp = NULL;
> >
> >         if (!log)
> >                 return;
> >
> > -       frag = list_last_entry(log, struct kunit_log_frag, list);
> > -       log_len = strlen(frag->buf);
> > -       len_left = sizeof(frag->buf) - log_len - 1;
> > -
> >         /* Evaluate length of line to add to log */
> >         va_start(args, fmt);
> >         len = vsnprintf(NULL, 0, fmt, args) + 1;
> >         va_end(args);
> >
> > +       if (len > sizeof(frag->buf) - 1) {
> > +               va_start(args, fmt);
> > +               tmp = kvasprintf(GFP_KERNEL, fmt, args);
> > +               va_end(args);
> > +
>
> Should we handle the case where kvasprintf() fails here and drop the
> log message?
>
>
> > +               kunit_log_append_string(log, tmp);
> > +               kfree(tmp);
> > +
> > +               return;
> > +       }
> > +
> > +       frag = list_last_entry(log, struct kunit_log_frag, list);
> > +       log_len = strlen(frag->buf);
> > +       len_left = sizeof(frag->buf) - log_len - 1;
> > +
> >         if (len > len_left) {
> >                 frag = kunit_log_extend(log);
> >                 if (!frag)
> > --
> > 2.30.2
> >
Rae Moar Aug. 10, 2023, 11:02 p.m. UTC | #2
On Wed, Aug 9, 2023 at 10:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Add a test that logging a string containing only a newline appends
> one newline to the log.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>

This is a really great idea to include a test for the simple addition
of only a newline character.

This patch looks good to me. The only comment is that the newline test
is quite large and could be broken up as I said on the previous patch.

Reviewed-by: Rae Moar <rmoar@google.com>

Thanks!
-Rae

> ---
>  lib/kunit/kunit-test.c | 6 ++++++
>  1 file changed, 6 insertions(+)
>
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index c079550c3afd..7e710c73c7e5 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -627,6 +627,12 @@ static void kunit_log_newline_test(struct kunit *test)
>                 kunit_init_log_frag(frag);
>                 list_add_tail(&frag->list, suite.log);
>
> +               /* Log only a newline */
> +               kunit_log_append(suite.log, "\n");
> +               KUNIT_EXPECT_TRUE(test, list_is_singular(suite.log));
> +               KUNIT_EXPECT_STREQ(test, frag->buf, "\n");
> +               frag->buf[0] = '\0';
> +
>                 /* String that exactly fills fragment leaving no room for \n */
>                 memset(frag->buf, 0, sizeof(frag->buf));
>                 memset(frag->buf, 'x', sizeof(frag->buf) - 9);
> --
> 2.30.2
>