All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH v2 1/3] kunit: fix bug in debugfs logs of parameterized tests
@ 2023-02-22 18:27 Rae Moar
  2023-02-22 18:27 ` [PATCH v2 2/3] kunit: fix bug in the order of lines in debugfs logs Rae Moar
  2023-02-22 18:27 ` [PATCH v2 3/3] kunit: fix bug of extra newline characters " Rae Moar
  0 siblings, 2 replies; 5+ messages in thread
From: Rae Moar @ 2023-02-22 18:27 UTC (permalink / raw)
  To: brendanhiggins, davidgow, dlatypov
  Cc: skhan, kunit-dev, linux-kernel, linux-kselftest, Rae Moar

Fix bug in debugfs logs that causes individual parameterized results to not
appear because the log is reinitialized (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. As a result, append lines to
the log directly rather than using an intermediate variable that can cause
stack size warnings due to the increased log size.

Here is the debugfs log of ext4_inode_test which uses parameterized tests
before the fix:

     KTAP version 1

     # Subtest: ext4_inode_test
     1..1
 # Totals: pass:16 fail:0 skip:0 total:16
 ok 1 ext4_inode_test

As you can see, this log does not include any of the individual
parametrized results.

After (in combination with the next two fixes to remove extra empty line
and ensure KTAP valid format):

 KTAP version 1
 1..1
     KTAP version 1
     # Subtest: ext4_inode_test
     1..1
        KTAP version 1
         # Subtest: inode_test_xtimestamp_decoding
	 ok 1 1901-12-13 Lower bound of 32bit < 0 timestamp, no extra bits
	 … (the rest of the individual parameterized tests)
         ok 16 2446-05-10 Upper bound of 32bit >=0 timestamp. All extra
     # inode_test_xtimestamp_decoding: pass:16 fail:0 skip:0 total:16
     ok 1 inode_test_xtimestamp_decoding
 # Totals: pass:16 fail:0 skip:0 total:16
 ok 1 ext4_inode_test

Signed-off-by: Rae Moar <rmoar@google.com>
Reviewed-by: David Gow <davidgow@google.com>
---

Changes from v1 -> v2:
- Remove the use of the line variable in kunit_log_append that was causing
  stack size warnings.
- Add before and after to the commit message.

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

diff --git a/include/kunit/test.h b/include/kunit/test.h
index 08d3559dd703..0668d29f3453 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 c9e15bb60058..c406aa07d875 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -114,22 +114,26 @@ static void kunit_print_test_stats(struct kunit *test,
  */
 void kunit_log_append(char *log, const char *fmt, ...)
 {
-	char line[KUNIT_LOG_SIZE];
 	va_list args;
-	int len_left;
+	int len, log_len, len_left;
 
 	if (!log)
 		return;
 
-	len_left = KUNIT_LOG_SIZE - strlen(log) - 1;
+	log_len = strlen(log);
+	len_left = KUNIT_LOG_SIZE - log_len - 1;
 	if (len_left <= 0)
 		return;
 
+	/* Evaluate length of line to add to log */
 	va_start(args, fmt);
-	vsnprintf(line, sizeof(line), fmt, args);
+	len = vsnprintf(NULL, 0, fmt, args);
 	va_end(args);
 
-	strncat(log, line, len_left);
+	/* Print formatted line to the log */
+	va_start(args, fmt);
+	vsnprintf(log + log_len, min(len, len_left), fmt, args);
+	va_end(args);
 }
 EXPORT_SYMBOL_GPL(kunit_log_append);
 
@@ -437,7 +441,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 +536,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);

base-commit: 82649c7c0da431d147a75c6ae768ee42c1053f53
-- 
2.39.2.637.g21b0678d19-goog


^ permalink raw reply related	[flat|nested] 5+ messages in thread

* [PATCH v2 2/3] kunit: fix bug in the order of lines in debugfs logs
  2023-02-22 18:27 [PATCH v2 1/3] kunit: fix bug in debugfs logs of parameterized tests Rae Moar
@ 2023-02-22 18:27 ` Rae Moar
  2023-02-22 18:27 ` [PATCH v2 3/3] kunit: fix bug of extra newline characters " Rae Moar
  1 sibling, 0 replies; 5+ messages in thread
From: Rae Moar @ 2023-02-22 18:27 UTC (permalink / raw)
  To: brendanhiggins, davidgow, dlatypov
  Cc: skhan, kunit-dev, linux-kernel, linux-kselftest, Rae Moar

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

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

Ensure the order of printing for the debugfs log is correct. Additionally,
add a KTAP header to so the debugfs logs can be valid KTAP.

This is an example of the kunit_status 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 the two lines with stats are out of order. This is the same debugfs
log after the fixes (in combination with the third patch to remove the
extra line):

 KTAP version 1
 1..1
     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 1 kunit_status

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

Changes from v1 -> v2:
- Add KTAP header.
- Ensure test result number is 1.
- Add before and after results to the commit message.

 lib/kunit/debugfs.c | 14 ++++++++++++--
 lib/kunit/test.c    | 21 ++++++++++++++-------
 2 files changed, 26 insertions(+), 9 deletions(-)

diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c
index de0ee2e03ed6..b08bb1fba106 100644
--- a/lib/kunit/debugfs.c
+++ b/lib/kunit/debugfs.c
@@ -55,14 +55,24 @@ static int debugfs_print_results(struct seq_file *seq, void *v)
 	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 KTAP header so the debugfs log can be parsed as valid KTAP. */
+	seq_puts(seq, "KTAP version 1\n");
+	seq_puts(seq, "1..1\n");
+
+	/* 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);
 
+	if (suite->log)
+		seq_printf(seq, "%s", suite->log);
+
 	seq_printf(seq, "%s %d %s\n",
 		   kunit_status_to_ok_not_ok(success), 1, suite->name);
 	return 0;
diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index c406aa07d875..fb6b39cca0ae 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -151,10 +151,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\n",
 		  suite->name);
-	kunit_log(KERN_INFO, suite, KUNIT_SUBTEST_INDENT "1..%zd",
+	pr_info(KUNIT_SUBTEST_INDENT "1..%zd\n",
 		  kunit_suite_num_test_cases(suite));
 }
 
@@ -171,10 +179,9 @@ static void kunit_print_ok_not_ok(void *test_or_suite,
 
 	/*
 	 * 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
+	 * mean debugfs display would consist of an incorrect test
+	 * number. Hence directly printk the suite result, and we will
+	 * separately seq_printf() the suite results for the debugfs
 	 * representation.
 	 */
 	if (suite)
-- 
2.39.2.637.g21b0678d19-goog


^ permalink raw reply related	[flat|nested] 5+ messages in thread

* [PATCH v2 3/3] kunit: fix bug of extra newline characters in debugfs logs
  2023-02-22 18:27 [PATCH v2 1/3] kunit: fix bug in debugfs logs of parameterized tests Rae Moar
  2023-02-22 18:27 ` [PATCH v2 2/3] kunit: fix bug in the order of lines in debugfs logs Rae Moar
@ 2023-02-22 18:27 ` Rae Moar
  2023-02-23  5:51   ` David Gow
  1 sibling, 1 reply; 5+ messages in thread
From: Rae Moar @ 2023-02-22 18:27 UTC (permalink / raw)
  To: brendanhiggins, davidgow, dlatypov
  Cc: skhan, kunit-dev, linux-kernel, linux-kselftest, 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.

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

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);
 
-- 
2.39.2.637.g21b0678d19-goog


^ permalink raw reply related	[flat|nested] 5+ messages in thread

* Re: [PATCH v2 3/3] kunit: fix bug of extra newline characters in debugfs logs
  2023-02-22 18:27 ` [PATCH v2 3/3] kunit: fix bug of extra newline characters " Rae Moar
@ 2023-02-23  5:51   ` David Gow
  2023-02-23 21:45     ` Rae Moar
  0 siblings, 1 reply; 5+ messages in thread
From: David Gow @ 2023-02-23  5:51 UTC (permalink / raw)
  To: Rae Moar
  Cc: brendanhiggins, dlatypov, skhan, kunit-dev, linux-kernel,
	linux-kselftest

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

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
>

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

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH v2 3/3] kunit: fix bug of extra newline characters in debugfs logs
  2023-02-23  5:51   ` David Gow
@ 2023-02-23 21:45     ` Rae Moar
  0 siblings, 0 replies; 5+ messages in thread
From: Rae Moar @ 2023-02-23 21:45 UTC (permalink / raw)
  To: David Gow
  Cc: brendanhiggins, dlatypov, skhan, kunit-dev, linux-kernel,
	linux-kselftest

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

^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2023-02-23 21:45 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2023-02-22 18:27 [PATCH v2 1/3] kunit: fix bug in debugfs logs of parameterized tests Rae Moar
2023-02-22 18:27 ` [PATCH v2 2/3] kunit: fix bug in the order of lines in debugfs logs Rae Moar
2023-02-22 18:27 ` [PATCH v2 3/3] kunit: fix bug of extra newline characters " Rae Moar
2023-02-23  5:51   ` David Gow
2023-02-23 21:45     ` Rae Moar

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.