Date:   Wed, 22 Feb 2023 18:27:40 +0000
In-Reply-To: <20230222182740.254087-1-rmoar@google.com>
Mime-Version: 1.0
References: <20230222182740.254087-1-rmoar@google.com>
Message-ID: <20230222182740.254087-3-rmoar@google.com>
Subject: [PATCH v2 3/3] kunit: fix bug of extra newline characters in debugfs logs
From:   Rae Moar <rmoar@google.com>
To:     brendanhiggins@google.com, davidgow@google.com, dlatypov@google.com
Cc:     skhan@linuxfoundation.org, kunit-dev@googlegroups.com,
        linux-kernel@vger.kernel.org, linux-kselftest@vger.kernel.org,
        Rae Moar <rmoar@google.com>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

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(..., =E2=80=9CKTAP version 1\n=E2=80=9D);
kunit_log(..., =E2=80=9C1..1=E2=80=9D);

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
=20
 void kunit_cleanup(struct kunit *test);
=20
+/**
+ * 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, ...);
=20
 /**
@@ -420,7 +427,7 @@ void __printf(2, 3) kunit_log_append(char *log, const c=
har *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)
=20
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 =
=3D {
 	.test_cases =3D kunit_resource_test_cases,
 };
=20
-static void kunit_log_test(struct kunit *test);
-
-static struct kunit_case kunit_log_test_cases[] =3D {
-	KUNIT_CASE(kunit_log_test),
-	{}
-};
-
-static struct kunit_suite kunit_log_test_suite =3D {
-	.name =3D "kunit-log-test",
-	.test_cases =3D 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
 }
=20
+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[] =3D {
+	KUNIT_CASE(kunit_log_test),
+	KUNIT_CASE(kunit_log_newline_test),
+	{}
+};
+
+static struct kunit_suite kunit_log_test_suite =3D {
+	.name =3D "kunit-log-test",
+	.test_cases =3D 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);
 }
=20
+void kunit_log_newline(char *log)
+{
+	int log_len, len_left;
+
+	log_len =3D strlen(log);
+	len_left =3D KUNIT_LOG_SIZE - log_len - 1;
+
+	if (log_len > 0 && log[log_len - 1] !=3D '\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);
=20
--=20
2.39.2.637.g21b0678d19-goog