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 in debugfs logs that causes parameterized results to not appear in the log because the log is reintialized (cleared) when each parameter is

Hi David!

Nit: s/reintialized/reinitialized

Oops. Thanks for pointing this out. Will fix in v2.

...

run.

Ensure these results appear in the debugfs logs and increase log size to allow for the size of parameterized results.

Signed-off-by: Rae Moar rmoar@google.com

This looks pretty good to me, but we may need to restrict the size of a single log line separately from that of the whole log.

(It'd also be nice to include a before/after in the commit description.)

Yes, as mentioned in the other patches, 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.

With the stack size issue fixed, though, this looks good to me: Reviewed-by: David Gow davidgow@google.com

Cheers, -- David

...

include/kunit/test.h | 2 +- lib/kunit/test.c | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/include/kunit/test.h b/include/kunit/test.h index 87ea90576b50..0a077a4c067c 100644 --- a/include/kunit/test.h +++ b/include/kunit/test.h @@ -34,7 +34,7 @@ DECLARE_STATIC_KEY_FALSE(kunit_running); struct kunit;

/* Size of log associated with test. */ -#define KUNIT_LOG_SIZE 512 +#define KUNIT_LOG_SIZE 1500

This is used both as the overall log size, and the size of a single line in kunit_log_append.

As the latter involves a local 'line' array, it can bloat out stack usage.

Could we either restrict the maximum line length separately, or rework kunit_log_append() to not use a local variable? (I imagine we could just vsnprintf() directly into the log buffer. We could make two sprintf calls to calculate the length required to maintain some atomicity as well (this could open us up to time-of-check/time-of-use vulnerabilities, but I think the vulnerability ship has sailed if you're passing untrusted pointers into the kunit_log macro anyway))

Thanks for your help here. I will play around with these two options. Although, I think I am leaning toward restricting the maximum line length separately.

Thanks!

-Rae

...

/* Maximum size of parameter description string. */ #define KUNIT_PARAM_DESC_SIZE 128 diff --git a/lib/kunit/test.c b/lib/kunit/test.c index 51cae59d8aae..66ba93b8222c 100644 --- a/lib/kunit/test.c +++ b/lib/kunit/test.c @@ -437,7 +437,6 @@ static void kunit_run_case_catch_errors(struct kunit_suite *suite, struct kunit_try_catch_context context; struct kunit_try_catch *try_catch;

•   kunit_init_test(test, test_case->name, test_case->log);
    try_catch = &test->try_catch;
  
    kunit_try_catch_init(try_catch,
  

@@ -533,6 +532,8 @@ int kunit_run_tests(struct kunit_suite *suite) struct kunit_result_stats param_stats = { 0 }; test_case->status = KUNIT_SKIPPED;

•           kunit_init_test(&test, test_case->name, test_case->log);
  

•           if (!test_case->generate_params) {
                    /* Non-parameterised test. */
                    kunit_run_case_catch_errors(suite, test_case, &test);
  

-- 2.39.1.456.gfc5497dd1b-goog

On Wed, 1 Feb 2023 at 06:04, Rae Moar rmoar@google.com wrote:

Fix bug in debugfs logs that causes an incorrect order of lines in the debugfs log.

Currently, any suite diagnostic lines, including the test counts lines that show the number of tests passed, failed, and skipped, appear prior to the individual results, which is a bug.

Ensure the order of printing for the debugfs log is correct.

Signed-off-by: Rae Moar rmoar@google.com

I think this is overall an improvement, but there are a few remaining issues (some new, some old).

First, as with the previous patches, could we have a before/after comparison in the commit description?

Secondly, I think it'd be nice to either add an extra KTAP header to the start, so that each debugfs results file is a valid KTAP document by itself, or at least document that you'll need to prepend one for this to work. I'm personally leaning towards the latter, even if it loses us the ability to just concatenate result files together, because of the third issue below.

Finally, with this patch, the final result line's suite number is recorded from its initial run, rather than always being '1'. This means that if multiple suites are run (e.g. list-test.ko), then the result file could contain a single suite, with "ok 2 ..." or similar as a result line. This might help a bit if we were concatenating result files, but otherwise leaves us with a parse error due to the mismatched number.

Personally, I'd prefer we change those to always use suite number 1, and to add the KTAP header to the start. Adding the header should be easy, the suite number perhaps less so...

Cheers, -- David

lib/kunit/debugfs.c | 13 ++++++++----- lib/kunit/test.c | 24 ++++++++++++------------ 2 files changed, 20 insertions(+), 17 deletions(-)

diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c index de0ee2e03ed6..fbc645590701 100644 --- a/lib/kunit/debugfs.c +++ b/lib/kunit/debugfs.c @@ -52,19 +52,22 @@ static void debugfs_print_result(struct seq_file *seq, static int debugfs_print_results(struct seq_file *seq, void *v) { struct kunit_suite *suite = (struct kunit_suite *)seq->private;

•   enum kunit_status success = kunit_suite_has_succeeded(suite);
    struct kunit_case *test_case;
  
  

•   if (!suite || !suite->log)
  

•   if (!suite)
            return 0;
  
  

•   seq_printf(seq, "%s", suite->log);
  

•   /* Print suite header because it is not stored in the test logs. */
  

•   seq_puts(seq, KUNIT_SUBTEST_INDENT "KTAP version 1\n");
  

We probably want to print this twice, once without the indent, to start the whole document, once with it.

•   seq_printf(seq, KUNIT_SUBTEST_INDENT "# Subtest: %s\n", suite->name);
  

•   seq_printf(seq, KUNIT_SUBTEST_INDENT "1..%zd\n", kunit_suite_num_test_cases(suite));
  
    kunit_suite_for_each_test_case(suite, test_case)
            debugfs_print_result(seq, suite, test_case);
  
  

•   seq_printf(seq, "%s %d %s\n",
  

•              kunit_status_to_ok_not_ok(success), 1, suite->name);
  

We probably still want to output the suite number as '1'...

•   if (suite->log)
  

•           seq_printf(seq, "%s", suite->log);
  

•   return 0;
  

}

diff --git a/lib/kunit/test.c b/lib/kunit/test.c index 66ba93b8222c..27763f0b420c 100644 --- a/lib/kunit/test.c +++ b/lib/kunit/test.c @@ -147,10 +147,18 @@ EXPORT_SYMBOL_GPL(kunit_suite_num_test_cases);

static void kunit_print_suite_start(struct kunit_suite *suite) {

•   kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "KTAP version 1\n");
  

•   kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "# Subtest: %s",
  

•   /*
  

•    * We do not log the test suite header as doing so would
  

•    * mean debugfs display would consist of the test suite
  

•    * header prior to individual test results.
  

•    * Hence directly printk the suite status, and we will
  

•    * separately seq_printf() the suite header for the debugfs
  

•    * representation.
  

•    */
  

•   pr_info(KUNIT_SUBTEST_INDENT "KTAP version 1\n");
  

•   pr_info(KUNIT_SUBTEST_INDENT "# Subtest: %s",
              suite->name);
  

•   kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "1..%zd",
  

•   pr_info(KUNIT_SUBTEST_INDENT "1..%zd",
              kunit_suite_num_test_cases(suite));
  

}

@@ -165,16 +173,8 @@ static void kunit_print_ok_not_ok(void *test_or_suite, struct kunit *test = is_test ? test_or_suite : NULL; const char *directive_header = (status == KUNIT_SKIPPED) ? " # SKIP " : "";

•   /*
  

•    * We do not log the test suite results as doing so would
  

•    * mean debugfs display would consist of the test suite
  

•    * description and status prior to individual test results.
  

•    * Hence directly printk the suite status, and we will
  

•    * separately seq_printf() the suite status for the debugfs
  

•    * representation.
  

•    */
    if (suite)
  

•           pr_info("%s %zd %s%s%s\n",
  

•           kunit_log(KERN_INFO, suite, "%s %zd %s%s%s\n",
  

Changing this breaks the code to ensure the suite number is always '1'...

                    kunit_status_to_ok_not_ok(status),
                    test_number, description, directive_header,
                    (status == KUNIT_SKIPPED) ? directive : "");

-- 2.39.1.456.gfc5497dd1b-goog

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