| Message ID | 20230222182740.254087-3-rmoar@google.com (mailing list archive) |
|---|---|
| State | New |
| Delegated to: | Brendan Higgins |
| Headers | show |
| Series | [v2,1/3] kunit: fix bug in debugfs logs of parameterized tests | expand |
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 appears > 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 newline Nit: "if the 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. (Also, > 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(..., “KTAP version 1\n”); > kunit_log(..., “1..1”); Nit: Please use regular quotes here ("), rather than the "smart 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 bit > 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 bit > 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 *test, 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? > 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, const 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_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,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[] = { > + KUNIT_CASE(kunit_log_test), This test is failing now: [13:42:51] =============== kunit-log-test (2 subtests) ================ [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 is [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] ================= [FAILED] 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 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 *test, > stats.total); > } > > +void kunit_log_newline(char *log) > +{ > + int log_len, len_left; > + > + log_len = strlen(log); > + len_left = KUNIT_LOG_SIZE - log_len - 1; > + > + if (log_len > 0 && log[log_len - 1] != '\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 >
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 appears > > 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 newline > > 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. (Also, > > 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(..., “KTAP version 1\n”); > > kunit_log(..., “1..1”); > > Nit: Please use regular quotes here ("), rather than the "smart quotes" (“”). 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 bit > > 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 bit > > 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 *test, 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, const 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_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,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[] = { > > + KUNIT_CASE(kunit_log_test), > > This test is failing now: > [13:42:51] =============== kunit-log-test (2 subtests) ================ > [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 is > [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] ================= [FAILED] kunit-log-test ================== > 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 = vsnprintf(NULL, 0, fmt, args); + len = 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 = { > > + .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 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 *test, > > stats.total); > > } > > > > +void kunit_log_newline(char *log) > > +{ > > + int log_len, len_left; > > + > > + log_len = strlen(log); > > + len_left = KUNIT_LOG_SIZE - log_len - 1; > > + > > + if (log_len > 0 && log[log_len - 1] != '\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 > >
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 *test, 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); + 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, const 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_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,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[] = { + 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 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 *test, stats.total); } +void kunit_log_newline(char *log) +{ + int log_len, len_left; + + log_len = strlen(log); + len_left = KUNIT_LOG_SIZE - log_len - 1; + + if (log_len > 0 && log[log_len - 1] != '\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);
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. 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 newline 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. (Also, 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(..., “KTAP version 1\n”); kunit_log(..., “1..1”); 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> --- 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 bit 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 bit 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(-)