Re: [PATCH v3 3/7] kunit: Handle logging of lines longer than the fragment buffer size

[David Gow]

On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
<rf@xxxxxxxxxxxxxxxxxxxxx> 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@xxxxxxxxxxxxxxxxxxxxx>
> ---

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. :-)

But in my eyes, this is
Reviewed-by: David Gow <davidgow@xxxxxxxxxx>

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
>