diff mbox series

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

Message ID 20230131220355.1603527-4-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 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@google.com>
---
 lib/kunit/kunit-test.c | 36 ++++++++++++++++++++++++------------
 lib/kunit/test.c       |  9 ++++++++-
 2 files changed, 32 insertions(+), 13 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 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@google.com>
> ---

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?

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.

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?

I do like the move of kunit_log_test though. That definitely cleans things up!

Cheers,
-- David


>  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
>
Rae Moar Feb. 10, 2023, 7:46 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 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@google.com>
> > ---

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
> >
diff mbox series

Patch

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);