[PATCH v1 0/3] kunit: fix bugs in debugfs logs

[PATCH v1 0/3] kunit: fix bugs in debugfs logs

[Rae Moar]

Currently, the KUnit debugfs logs have a few issues:
1. The results of parameterized tests don’t show up
2. The order of the lines in the logs is sometimes incorrect
3. There are extra new lines in the logs

This patch series aims to fix these issues.

This is an example of a debugfs log prior to these fixes:

   KTAP version 1

   # Subtest: kunit_status
   1..2
 # kunit_status: pass:2 fail:0 skip:0 total:2
 # Totals: pass:2 fail:0 skip:0 total:2
   ok 1 kunit_status_set_failure_test
   ok 2 kunit_status_mark_skipped_test
 ok 1 kunit_status

Note there is an extra line and a few of the lines are out of order.

This is the same debugfs log after the fixes:

   KTAP version 1
   # Subtest: kunit_status
   1..2
   ok 1 kunit_status_set_failure_test
   ok 2 kunit_status_mark_skipped_test
 # kunit_status: pass:2 fail:0 skip:0 total:2
 # Totals: pass:2 fail:0 skip:0 total:2
 ok 4 kunit_status

This is now equivalent to the regular KTAP output for the kunit_status
test.

Thanks!
-Rae

Rae Moar (3):
  kunit: fix bug in debugfs logs of parameterized tests
  kunit: fix bug in the order of lines in debugfs logs
  kunit: fix bug of extra newline characters in debugfs logs

 include/kunit/test.h   |  2 +-
 lib/kunit/debugfs.c    | 13 ++++++++-----
 lib/kunit/kunit-test.c | 36 ++++++++++++++++++++++++------------
 lib/kunit/test.c       | 36 ++++++++++++++++++++++--------------
 4 files changed, 55 insertions(+), 32 deletions(-)


base-commit: 766f4f2514d2d18bcbd60a058188fb502dea5ddf
-- 
2.39.1.456.gfc5497dd1b-goog

[PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests

[Rae Moar]

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
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>
---
 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
 
 /* 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

[PATCH v1 2/3] kunit: fix bug in the order of lines in debugfs logs

[Rae Moar]

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>
---
 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");
+	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);
+	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",
 			kunit_status_to_ok_not_ok(status),
 			test_number, description, directive_header,
 			(status == KUNIT_SKIPPED) ? directive : "");
-- 
2.39.1.456.gfc5497dd1b-goog

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

[Rae Moar]

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

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

Re: [PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests

[kernel test robot]

Hi Rae,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on 766f4f2514d2d18bcbd60a058188fb502dea5ddf]

url:    https://github.com/intel-lab-lkp/linux/commits/Rae-Moar/kunit-fix-bug-in-debugfs-logs-of-parameterized-tests/20230201-060537
base:   766f4f2514d2d18bcbd60a058188fb502dea5ddf
patch link:    https://lore.kernel.org/r/20230131220355.1603527-2-rmoar%40google.com
patch subject: [PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests
config: m68k-allyesconfig (https://download.01.org/0day-ci/archive/20230201/202302010709.7ZmEen4w-lkp@intel.com/config)
compiler: m68k-linux-gcc (GCC) 12.1.0
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/intel-lab-lkp/linux/commit/c8b669e1d139e1ee08121b184d859e45d7a02940
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Rae-Moar/kunit-fix-bug-in-debugfs-logs-of-parameterized-tests/20230201-060537
        git checkout c8b669e1d139e1ee08121b184d859e45d7a02940
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-12.1.0 make.cross W=1 O=build_dir ARCH=m68k olddefconfig
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-12.1.0 make.cross W=1 O=build_dir ARCH=m68k SHELL=/bin/bash lib/

If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>

All warnings (new ones prefixed by >>):

   lib/kunit/test.c: In function '__kunit_fail_current_test_impl':
   lib/kunit/test.c:40:9: warning: function '__kunit_fail_current_test_impl' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
      40 |         len = vsnprintf(NULL, 0, fmt, args) + 1;
         |         ^~~
   lib/kunit/test.c:48:9: warning: function '__kunit_fail_current_test_impl' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
      48 |         vsnprintf(buffer, len, fmt, args);
         |         ^~~~~~~~~
   lib/kunit/test.c: In function 'kunit_log_append':
>> lib/kunit/test.c:133:1: warning: the frame size of 1500 bytes is larger than 1024 bytes [-Wframe-larger-than=]
     133 | }
         | ^


vim +133 lib/kunit/test.c

acd8e8407b8fcc David Gow    2021-08-03  110  
e2219db280e3fe Alan Maguire 2020-03-26  111  /*
e2219db280e3fe Alan Maguire 2020-03-26  112   * Append formatted message to log, size of which is limited to
e2219db280e3fe Alan Maguire 2020-03-26  113   * KUNIT_LOG_SIZE bytes (including null terminating byte).
e2219db280e3fe Alan Maguire 2020-03-26  114   */
e2219db280e3fe Alan Maguire 2020-03-26  115  void kunit_log_append(char *log, const char *fmt, ...)
e2219db280e3fe Alan Maguire 2020-03-26  116  {
e2219db280e3fe Alan Maguire 2020-03-26  117  	char line[KUNIT_LOG_SIZE];
e2219db280e3fe Alan Maguire 2020-03-26  118  	va_list args;
e2219db280e3fe Alan Maguire 2020-03-26  119  	int len_left;
e2219db280e3fe Alan Maguire 2020-03-26  120  
e2219db280e3fe Alan Maguire 2020-03-26  121  	if (!log)
e2219db280e3fe Alan Maguire 2020-03-26  122  		return;
e2219db280e3fe Alan Maguire 2020-03-26  123  
e2219db280e3fe Alan Maguire 2020-03-26  124  	len_left = KUNIT_LOG_SIZE - strlen(log) - 1;
e2219db280e3fe Alan Maguire 2020-03-26  125  	if (len_left <= 0)
e2219db280e3fe Alan Maguire 2020-03-26  126  		return;
e2219db280e3fe Alan Maguire 2020-03-26  127  
e2219db280e3fe Alan Maguire 2020-03-26  128  	va_start(args, fmt);
e2219db280e3fe Alan Maguire 2020-03-26  129  	vsnprintf(line, sizeof(line), fmt, args);
e2219db280e3fe Alan Maguire 2020-03-26  130  	va_end(args);
e2219db280e3fe Alan Maguire 2020-03-26  131  
e2219db280e3fe Alan Maguire 2020-03-26  132  	strncat(log, line, len_left);
e2219db280e3fe Alan Maguire 2020-03-26 @133  }
e2219db280e3fe Alan Maguire 2020-03-26  134  EXPORT_SYMBOL_GPL(kunit_log_append);
e2219db280e3fe Alan Maguire 2020-03-26  135  

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Re: [PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests

[kernel test robot]

Hi Rae,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on 766f4f2514d2d18bcbd60a058188fb502dea5ddf]

url:    https://github.com/intel-lab-lkp/linux/commits/Rae-Moar/kunit-fix-bug-in-debugfs-logs-of-parameterized-tests/20230201-060537
base:   766f4f2514d2d18bcbd60a058188fb502dea5ddf
patch link:    https://lore.kernel.org/r/20230131220355.1603527-2-rmoar%40google.com
patch subject: [PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests
config: hexagon-randconfig-r045-20230202 (https://download.01.org/0day-ci/archive/20230203/202302031414.TsTAA8Dr-lkp@intel.com/config)
compiler: clang version 16.0.0 (https://github.com/llvm/llvm-project 4196ca3278f78c6e19246e54ab0ecb364e37d66a)
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/intel-lab-lkp/linux/commit/c8b669e1d139e1ee08121b184d859e45d7a02940
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Rae-Moar/kunit-fix-bug-in-debugfs-logs-of-parameterized-tests/20230201-060537
        git checkout c8b669e1d139e1ee08121b184d859e45d7a02940
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=hexagon olddefconfig
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=hexagon SHELL=/bin/bash lib/kunit/

If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>

All warnings (new ones prefixed by >>):

>> lib/kunit/test.c:115:6: warning: stack frame size (1536) exceeds limit (1024) in 'kunit_log_append' [-Wframe-larger-than]
   void kunit_log_append(char *log, const char *fmt, ...)
        ^
   12/1536 (0.78%) spills, 1524/1536 (99.22%) variables
   1 warning generated.


vim +/kunit_log_append +115 lib/kunit/test.c

acd8e8407b8fcc David Gow    2021-08-03  110  
e2219db280e3fe Alan Maguire 2020-03-26  111  /*
e2219db280e3fe Alan Maguire 2020-03-26  112   * Append formatted message to log, size of which is limited to
e2219db280e3fe Alan Maguire 2020-03-26  113   * KUNIT_LOG_SIZE bytes (including null terminating byte).
e2219db280e3fe Alan Maguire 2020-03-26  114   */
e2219db280e3fe Alan Maguire 2020-03-26 @115  void kunit_log_append(char *log, const char *fmt, ...)
e2219db280e3fe Alan Maguire 2020-03-26  116  {
e2219db280e3fe Alan Maguire 2020-03-26  117  	char line[KUNIT_LOG_SIZE];
e2219db280e3fe Alan Maguire 2020-03-26  118  	va_list args;
e2219db280e3fe Alan Maguire 2020-03-26  119  	int len_left;
e2219db280e3fe Alan Maguire 2020-03-26  120  
e2219db280e3fe Alan Maguire 2020-03-26  121  	if (!log)
e2219db280e3fe Alan Maguire 2020-03-26  122  		return;
e2219db280e3fe Alan Maguire 2020-03-26  123  
e2219db280e3fe Alan Maguire 2020-03-26  124  	len_left = KUNIT_LOG_SIZE - strlen(log) - 1;
e2219db280e3fe Alan Maguire 2020-03-26  125  	if (len_left <= 0)
e2219db280e3fe Alan Maguire 2020-03-26  126  		return;
e2219db280e3fe Alan Maguire 2020-03-26  127  
e2219db280e3fe Alan Maguire 2020-03-26  128  	va_start(args, fmt);
e2219db280e3fe Alan Maguire 2020-03-26  129  	vsnprintf(line, sizeof(line), fmt, args);
e2219db280e3fe Alan Maguire 2020-03-26  130  	va_end(args);
e2219db280e3fe Alan Maguire 2020-03-26  131  
e2219db280e3fe Alan Maguire 2020-03-26  132  	strncat(log, line, len_left);
e2219db280e3fe Alan Maguire 2020-03-26  133  }
e2219db280e3fe Alan Maguire 2020-03-26  134  EXPORT_SYMBOL_GPL(kunit_log_append);
e2219db280e3fe Alan Maguire 2020-03-26  135  

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Re: [PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests

[David Gow]

[-- Attachment #1: Type: text/plain, Size: 2941 bytes --]

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

Nit: s/reintialized/reinitialized

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

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

>
>  /* 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
>

[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 4003 bytes --]

Re: [PATCH v1 2/3] kunit: fix bug in the order of lines in debugfs logs

[David Gow]

[-- Attachment #1: Type: text/plain, Size: 5506 bytes --]

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
>

[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 4003 bytes --]

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

[David Gow]

[-- Attachment #1: Type: text/plain, Size: 4695 bytes --]

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
>

[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 4003 bytes --]

Re: [PATCH v1 2/3] kunit: fix bug in the order of lines in debugfs logs

[Rae Moar]

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

Hi David!

Thanks for your comments.

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

Yes, this sounds like a great idea. I originally thought the before
and after comparison in the cover letter would be sufficient but an
individual comparison for each patch is clearer. I will add this in
v2.

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

My intention was to match the logs with the exact KTAP output of the
test to be consistent. But I see the value in ensuring the logs are
easily parsable. In v2, I will add the KTAP header and change the test
number to be 1 to allow the logs to be parsed without error.

-Rae

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

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

[Rae Moar]

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

Re: [PATCH v1 1/3] kunit: fix bug in debugfs logs of parameterized tests

[Rae Moar]

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