[PATCH v3 0/7] kunit: Add dynamically-extending log

[PATCH v3 0/7] kunit: Add dynamically-extending log

[Richard Fitzgerald]

Replace the original fixed-size log buffer with a dynamically-
extending log.

Patch 1 provides the basic implementation. The following patches
add test cases, support for logging long strings, and an optimization
to the string formatting that is now more thoroughly testable.

Changes since v2:
- Fixed uninitialized string bug in get_concatenated_log().
- Moved get_concatenated_log() into first patch so that
  kunit_log_newline_test() dumps the entire log on error.
- Moved kunit_log_frag_sized_line_test() to the correct point in
  the chain, after the change that it depends on. Also log another
  line after the long line to test that the log extends correctly.
- Added kunit_log_init_frag_test() to test kunit_init_log_frag()
  instead of testing it as part of every other test.

Richard Fitzgerald (7):
  kunit: Replace fixed-size log with dynamically-extending buffer
  kunit: kunit-test: Add test cases for extending log buffer
  kunit: Handle logging of lines longer than the fragment buffer size
  kunit: kunit-test: Test logging a line that exactly fills a fragment
  kunit: kunit-test: Add test cases for logging very long lines
  kunit: kunit-test: Add test of logging only a newline
  kunit: Don't waste first attempt to format string in
    kunit_log_append()

 include/kunit/test.h   |  25 ++-
 lib/kunit/debugfs.c    |  65 ++++++--
 lib/kunit/kunit-test.c | 339 ++++++++++++++++++++++++++++++++++++++++-
 lib/kunit/test.c       | 127 ++++++++++++---
 4 files changed, 507 insertions(+), 49 deletions(-)

-- 
2.30.2

[PATCH v3 1/7] kunit: Replace fixed-size log with dynamically-extending buffer

[Richard Fitzgerald]

Re-implement the log buffer as a list of buffer fragments that can
be extended as the size of the log info grows.

When using parameterization the test case can run many times and create
a large amount of log. It's not really practical to keep increasing the
size of the fixed buffer every time a test needs more space. And a big
fixed buffer wastes memory.

The original char *log pointer is replaced by a pointer to a list of
struct kunit_log_frag, each containing a fixed-size buffer.

kunit_log_append() now attempts to append to the last kunit_log_frag in
the list. If there isn't enough space it will append a new kunit_log_frag
to the list. This simple implementation does not attempt to completely
fill the buffer in every kunit_log_frag.

The 'log' member of kunit_suite, kunit_test_case and kunit_suite must be a
pointer because the API of kunit_log() requires that is the same type in
all  three structs. As kunit.log is a pointer to the 'log' of the current
kunit_case, it must be a pointer in the other two structs.

The existing kunit-test.c log tests have been updated to build against the
new fragmented log implementation. If the test fails the new function
get_concatenated_log() constructs a single contiguous string from the
log fragments so that the whole log can be emitted in the failure
message.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 include/kunit/test.h   | 25 +++++++++++-----
 lib/kunit/debugfs.c    | 65 ++++++++++++++++++++++++++++++++++--------
 lib/kunit/kunit-test.c | 48 +++++++++++++++++++++++++------
 lib/kunit/test.c       | 63 ++++++++++++++++++++++++++++------------
 4 files changed, 155 insertions(+), 46 deletions(-)

diff --git a/include/kunit/test.h b/include/kunit/test.h
index d33114097d0d..cb5082efc91c 100644
--- a/include/kunit/test.h
+++ b/include/kunit/test.h
@@ -33,8 +33,8 @@ DECLARE_STATIC_KEY_FALSE(kunit_running);
 
 struct kunit;
 
-/* Size of log associated with test. */
-#define KUNIT_LOG_SIZE 2048
+/* Size of log buffer fragments. */
+#define KUNIT_LOG_FRAGMENT_SIZE (256 - sizeof(struct list_head))
 
 /* Maximum size of parameter description string. */
 #define KUNIT_PARAM_DESC_SIZE 128
@@ -85,6 +85,17 @@ struct kunit_attributes {
 	enum kunit_speed speed;
 };
 
+struct kunit_log_frag {
+	struct list_head list;
+	char buf[KUNIT_LOG_FRAGMENT_SIZE];
+};
+
+static inline void kunit_init_log_frag(struct kunit_log_frag *frag)
+{
+	INIT_LIST_HEAD(&frag->list);
+	frag->buf[0] = '\0';
+}
+
 /**
  * struct kunit_case - represents an individual test case.
  *
@@ -132,7 +143,7 @@ struct kunit_case {
 	/* private: internal use only. */
 	enum kunit_status status;
 	char *module_name;
-	char *log;
+	struct list_head *log;
 };
 
 static inline char *kunit_status_to_ok_not_ok(enum kunit_status status)
@@ -252,7 +263,7 @@ struct kunit_suite {
 	/* private: internal use only */
 	char status_comment[KUNIT_STATUS_COMMENT_SIZE];
 	struct dentry *debugfs;
-	char *log;
+	struct list_head *log;
 	int suite_init_err;
 };
 
@@ -278,7 +289,7 @@ struct kunit {
 
 	/* private: internal use only. */
 	const char *name; /* Read only after initialization! */
-	char *log; /* Points at case log after initialization */
+	struct list_head *log; /* Points at case log after initialization */
 	struct kunit_try_catch try_catch;
 	/* param_value is the current parameter value for a test case. */
 	const void *param_value;
@@ -314,7 +325,7 @@ const char *kunit_filter_glob(void);
 char *kunit_filter(void);
 char *kunit_filter_action(void);
 
-void kunit_init_test(struct kunit *test, const char *name, char *log);
+void kunit_init_test(struct kunit *test, const char *name, struct list_head *log);
 
 int kunit_run_tests(struct kunit_suite *suite);
 
@@ -472,7 +483,7 @@ static inline void *kunit_kcalloc(struct kunit *test, size_t n, size_t size, gfp
 
 void kunit_cleanup(struct kunit *test);
 
-void __printf(2, 3) kunit_log_append(char *log, const char *fmt, ...);
+void __printf(2, 3) kunit_log_append(struct list_head *log, const char *fmt, ...);
 
 /**
  * kunit_mark_skipped() - Marks @test_or_suite as skipped
diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c
index 22c5c496a68f..a26b6d31bd2f 100644
--- a/lib/kunit/debugfs.c
+++ b/lib/kunit/debugfs.c
@@ -5,6 +5,7 @@
  */
 
 #include <linux/debugfs.h>
+#include <linux/list.h>
 #include <linux/module.h>
 
 #include <kunit/test.h>
@@ -37,14 +38,15 @@ void kunit_debugfs_init(void)
 		debugfs_rootdir = debugfs_create_dir(KUNIT_DEBUGFS_ROOT, NULL);
 }
 
-static void debugfs_print_result(struct seq_file *seq,
-				 struct kunit_suite *suite,
-				 struct kunit_case *test_case)
+static void debugfs_print_log(struct seq_file *seq, const struct list_head *log)
 {
-	if (!test_case || !test_case->log)
+	struct kunit_log_frag *frag;
+
+	if (!log)
 		return;
 
-	seq_printf(seq, "%s", test_case->log);
+	list_for_each_entry(frag, log, list)
+		seq_puts(seq, frag->buf);
 }
 
 /*
@@ -69,10 +71,9 @@ static int debugfs_print_results(struct seq_file *seq, void *v)
 	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);
+		debugfs_print_log(seq, test_case->log);
 
-	if (suite->log)
-		seq_printf(seq, "%s", suite->log);
+	debugfs_print_log(seq, suite->log);
 
 	seq_printf(seq, "%s %d %s\n",
 		   kunit_status_to_ok_not_ok(success), 1, suite->name);
@@ -100,14 +101,53 @@ static const struct file_operations debugfs_results_fops = {
 	.release = debugfs_release,
 };
 
+static struct list_head *kunit_debugfs_alloc_log(void)
+{
+	struct list_head *log;
+	struct kunit_log_frag *frag;
+
+	log = kzalloc(sizeof(*log), GFP_KERNEL);
+	if (!log)
+		return NULL;
+
+	INIT_LIST_HEAD(log);
+
+	frag = kmalloc(sizeof(*frag), GFP_KERNEL);
+	if (!frag) {
+		kfree(log);
+		return NULL;
+	}
+
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, log);
+
+	return log;
+}
+
+static void kunit_debugfs_free_log(struct list_head *log)
+{
+	struct kunit_log_frag *frag, *n;
+
+	if (!log)
+		return;
+
+	list_for_each_entry_safe(frag, n, log, list) {
+		list_del(&frag->list);
+		kfree(frag);
+	}
+
+	kfree(log);
+}
+
 void kunit_debugfs_create_suite(struct kunit_suite *suite)
 {
 	struct kunit_case *test_case;
 
 	/* Allocate logs before creating debugfs representation. */
-	suite->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
+	suite->log = kunit_debugfs_alloc_log();
+
 	kunit_suite_for_each_test_case(suite, test_case)
-		test_case->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
+		test_case->log = kunit_debugfs_alloc_log();
 
 	suite->debugfs = debugfs_create_dir(suite->name, debugfs_rootdir);
 
@@ -121,7 +161,8 @@ void kunit_debugfs_destroy_suite(struct kunit_suite *suite)
 	struct kunit_case *test_case;
 
 	debugfs_remove_recursive(suite->debugfs);
-	kfree(suite->log);
+	kunit_debugfs_free_log(suite->log);
+
 	kunit_suite_for_each_test_case(suite, test_case)
-		kfree(test_case->log);
+		kunit_debugfs_free_log(test_case->log);
 }
diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index 83d8e90ca7a2..a199f83bac67 100644
--- a/lib/kunit/kunit-test.c
+++ b/lib/kunit/kunit-test.c
@@ -530,12 +530,37 @@ static struct kunit_suite kunit_resource_test_suite = {
 	.test_cases = kunit_resource_test_cases,
 };
 
+static char *get_concatenated_log(struct kunit *test, const struct list_head *log)
+{
+	struct kunit_log_frag *frag;
+	size_t len = 0;
+	char *p;
+
+	list_for_each_entry(frag, log, list)
+		len += strlen(frag->buf);
+
+	len++; /* for terminating '\0' */
+	p = kunit_kzalloc(test, len, GFP_KERNEL);
+
+	list_for_each_entry(frag, log, list)
+		strlcat(p, frag->buf, len);
+
+	return p;
+}
+
 static void kunit_log_test(struct kunit *test)
 {
 	struct kunit_suite suite;
+	struct kunit_log_frag *frag;
 
-	suite.log = kunit_kzalloc(test, KUNIT_LOG_SIZE, GFP_KERNEL);
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
 	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
+	KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
+	list_add_tail(&frag->list, suite.log);
 
 	kunit_log(KERN_INFO, test, "put this in log.");
 	kunit_log(KERN_INFO, test, "this too.");
@@ -543,14 +568,17 @@ static void kunit_log_test(struct kunit *test)
 	kunit_log(KERN_INFO, &suite, "along with this.");
 
 #ifdef CONFIG_KUNIT_DEBUGFS
+	frag = list_first_entry(test->log, struct kunit_log_frag, list);
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(test->log, "put this in log."));
+				     strstr(frag->buf, "put this in log."));
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(test->log, "this too."));
+				     strstr(frag->buf, "this too."));
+
+	frag = list_first_entry(suite.log, struct kunit_log_frag, list);
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(suite.log, "add to suite log."));
+				     strstr(frag->buf, "add to suite log."));
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(suite.log, "along with this."));
+				     strstr(frag->buf, "along with this."));
 #else
 	KUNIT_EXPECT_NULL(test, test->log);
 #endif
@@ -558,11 +586,15 @@ static void kunit_log_test(struct kunit *test)
 
 static void kunit_log_newline_test(struct kunit *test)
 {
+	struct kunit_log_frag *frag;
+
 	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"));
+		frag = list_first_entry(test->log, struct kunit_log_frag, list);
+		KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
+			"Missing log line, full log:\n%s",
+			get_concatenated_log(test, test->log));
+		KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
 	} else {
 		kunit_skip(test, "only useful when debugfs is enabled");
 	}
diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index 49698a168437..dfe51bc2b387 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -11,6 +11,7 @@
 #include <kunit/test-bug.h>
 #include <kunit/attributes.h>
 #include <linux/kernel.h>
+#include <linux/list.h>
 #include <linux/module.h>
 #include <linux/moduleparam.h>
 #include <linux/panic.h>
@@ -114,46 +115,66 @@ static void kunit_print_test_stats(struct kunit *test,
  * already present.
  * @log: The log to add the newline to.
  */
-static void kunit_log_newline(char *log)
+static void kunit_log_newline(struct kunit_log_frag *frag)
 {
 	int log_len, len_left;
 
-	log_len = strlen(log);
-	len_left = KUNIT_LOG_SIZE - log_len - 1;
+	log_len = strlen(frag->buf);
+	len_left = sizeof(frag->buf) - log_len - 1;
 
-	if (log_len > 0 && log[log_len - 1] != '\n')
-		strncat(log, "\n", len_left);
+	if (log_len > 0 && frag->buf[log_len - 1] != '\n')
+		strncat(frag->buf, "\n", len_left);
 }
 
-/*
- * Append formatted message to log, size of which is limited to
- * KUNIT_LOG_SIZE bytes (including null terminating byte).
- */
-void kunit_log_append(char *log, const char *fmt, ...)
+static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
+{
+	struct kunit_log_frag *frag;
+
+	frag = kmalloc(sizeof(*frag), GFP_KERNEL);
+	if (!frag)
+		return NULL;
+
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, log);
+
+	return frag;
+}
+
+/* Append formatted message to log, extending the log buffer if necessary. */
+void kunit_log_append(struct list_head *log, const char *fmt, ...)
 {
 	va_list args;
+	struct kunit_log_frag *frag;
 	int len, log_len, len_left;
 
 	if (!log)
 		return;
 
-	log_len = strlen(log);
-	len_left = KUNIT_LOG_SIZE - log_len - 1;
-	if (len_left <= 0)
-		return;
+	frag = list_last_entry(log, struct kunit_log_frag, list);
+	log_len = strlen(frag->buf);
+	len_left = sizeof(frag->buf) - log_len - 1;
 
 	/* Evaluate length of line to add to log */
 	va_start(args, fmt);
 	len = vsnprintf(NULL, 0, fmt, args) + 1;
 	va_end(args);
 
+	if (len > len_left) {
+		frag = kunit_log_extend(log);
+		if (!frag)
+			return;
+
+		len_left = sizeof(frag->buf) - 1;
+		log_len = 0;
+	}
+
 	/* Print formatted line to the log */
 	va_start(args, fmt);
-	vsnprintf(log + log_len, min(len, len_left), fmt, args);
+	vsnprintf(frag->buf + 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);
+	kunit_log_newline(frag);
 }
 EXPORT_SYMBOL_GPL(kunit_log_append);
 
@@ -359,14 +380,18 @@ void __kunit_do_failed_assertion(struct kunit *test,
 }
 EXPORT_SYMBOL_GPL(__kunit_do_failed_assertion);
 
-void kunit_init_test(struct kunit *test, const char *name, char *log)
+void kunit_init_test(struct kunit *test, const char *name, struct list_head *log)
 {
 	spin_lock_init(&test->lock);
 	INIT_LIST_HEAD(&test->resources);
 	test->name = name;
 	test->log = log;
-	if (test->log)
-		test->log[0] = '\0';
+	if (test->log) {
+		struct kunit_log_frag *frag = list_first_entry(test->log,
+							       struct kunit_log_frag,
+							       list);
+		frag->buf[0] = '\0';
+	}
 	test->status = KUNIT_SUCCESS;
 	test->status_comment[0] = '\0';
 }
-- 
2.30.2

Re: [PATCH v3 1/7] kunit: Replace fixed-size log with dynamically-extending buffer

[Rae Moar]

On Wed, Aug 9, 2023 at 11:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Re-implement the log buffer as a list of buffer fragments that can
> be extended as the size of the log info grows.
>
> When using parameterization the test case can run many times and create
> a large amount of log. It's not really practical to keep increasing the
> size of the fixed buffer every time a test needs more space. And a big
> fixed buffer wastes memory.
>
> The original char *log pointer is replaced by a pointer to a list of
> struct kunit_log_frag, each containing a fixed-size buffer.
>
> kunit_log_append() now attempts to append to the last kunit_log_frag in
> the list. If there isn't enough space it will append a new kunit_log_frag
> to the list. This simple implementation does not attempt to completely
> fill the buffer in every kunit_log_frag.
>
> The 'log' member of kunit_suite, kunit_test_case and kunit_suite must be a
> pointer because the API of kunit_log() requires that is the same type in
> all  three structs. As kunit.log is a pointer to the 'log' of the current
> kunit_case, it must be a pointer in the other two structs.
>
> The existing kunit-test.c log tests have been updated to build against the
> new fragmented log implementation. If the test fails the new function
> get_concatenated_log() constructs a single contiguous string from the
> log fragments so that the whole log can be emitted in the failure
> message.

Hello!

All the tests now pass for me and this patch now looks good to me. I
have tested it and it seems to be working well.

I just have a few nits below. But I am overall happy with this patch.

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

-Rae

>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> ---
>  include/kunit/test.h   | 25 +++++++++++-----
>  lib/kunit/debugfs.c    | 65 ++++++++++++++++++++++++++++++++++--------
>  lib/kunit/kunit-test.c | 48 +++++++++++++++++++++++++------
>  lib/kunit/test.c       | 63 ++++++++++++++++++++++++++++------------
>  4 files changed, 155 insertions(+), 46 deletions(-)
>
> diff --git a/include/kunit/test.h b/include/kunit/test.h
> index d33114097d0d..cb5082efc91c 100644
> --- a/include/kunit/test.h
> +++ b/include/kunit/test.h
> @@ -33,8 +33,8 @@ DECLARE_STATIC_KEY_FALSE(kunit_running);
>
>  struct kunit;
>
> -/* Size of log associated with test. */
> -#define KUNIT_LOG_SIZE 2048
> +/* Size of log buffer fragments. */
> +#define KUNIT_LOG_FRAGMENT_SIZE (256 - sizeof(struct list_head))
>
>  /* Maximum size of parameter description string. */
>  #define KUNIT_PARAM_DESC_SIZE 128
> @@ -85,6 +85,17 @@ struct kunit_attributes {
>         enum kunit_speed speed;
>  };
>
> +struct kunit_log_frag {
> +       struct list_head list;
> +       char buf[KUNIT_LOG_FRAGMENT_SIZE];
> +};
> +
> +static inline void kunit_init_log_frag(struct kunit_log_frag *frag)
> +{
> +       INIT_LIST_HEAD(&frag->list);
> +       frag->buf[0] = '\0';
> +}
> +
>  /**
>   * struct kunit_case - represents an individual test case.
>   *
> @@ -132,7 +143,7 @@ struct kunit_case {
>         /* private: internal use only. */
>         enum kunit_status status;
>         char *module_name;
> -       char *log;
> +       struct list_head *log;
>  };
>
>  static inline char *kunit_status_to_ok_not_ok(enum kunit_status status)
> @@ -252,7 +263,7 @@ struct kunit_suite {
>         /* private: internal use only */
>         char status_comment[KUNIT_STATUS_COMMENT_SIZE];
>         struct dentry *debugfs;
> -       char *log;
> +       struct list_head *log;
>         int suite_init_err;
>  };
>
> @@ -278,7 +289,7 @@ struct kunit {
>
>         /* private: internal use only. */
>         const char *name; /* Read only after initialization! */
> -       char *log; /* Points at case log after initialization */
> +       struct list_head *log; /* Points at case log after initialization */

To respond to some of the comments from the previous version, I am
fine with the list_head being a pointer considering there can only be
one list_head in this struct definition.

>         struct kunit_try_catch try_catch;
>         /* param_value is the current parameter value for a test case. */
>         const void *param_value;
> @@ -314,7 +325,7 @@ const char *kunit_filter_glob(void);
>  char *kunit_filter(void);
>  char *kunit_filter_action(void);
>
> -void kunit_init_test(struct kunit *test, const char *name, char *log);
> +void kunit_init_test(struct kunit *test, const char *name, struct list_head *log);
>
>  int kunit_run_tests(struct kunit_suite *suite);
>
> @@ -472,7 +483,7 @@ static inline void *kunit_kcalloc(struct kunit *test, size_t n, size_t size, gfp
>
>  void kunit_cleanup(struct kunit *test);
>
> -void __printf(2, 3) kunit_log_append(char *log, const char *fmt, ...);
> +void __printf(2, 3) kunit_log_append(struct list_head *log, const char *fmt, ...);
>
>  /**
>   * kunit_mark_skipped() - Marks @test_or_suite as skipped
> diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c
> index 22c5c496a68f..a26b6d31bd2f 100644
> --- a/lib/kunit/debugfs.c
> +++ b/lib/kunit/debugfs.c
> @@ -5,6 +5,7 @@
>   */
>
>  #include <linux/debugfs.h>
> +#include <linux/list.h>
>  #include <linux/module.h>
>
>  #include <kunit/test.h>
> @@ -37,14 +38,15 @@ void kunit_debugfs_init(void)
>                 debugfs_rootdir = debugfs_create_dir(KUNIT_DEBUGFS_ROOT, NULL);
>  }
>
> -static void debugfs_print_result(struct seq_file *seq,
> -                                struct kunit_suite *suite,
> -                                struct kunit_case *test_case)
> +static void debugfs_print_log(struct seq_file *seq, const struct list_head *log)
>  {
> -       if (!test_case || !test_case->log)
> +       struct kunit_log_frag *frag;
> +
> +       if (!log)
>                 return;
>
> -       seq_printf(seq, "%s", test_case->log);
> +       list_for_each_entry(frag, log, list)
> +               seq_puts(seq, frag->buf);
>  }
>
>  /*
> @@ -69,10 +71,9 @@ static int debugfs_print_results(struct seq_file *seq, void *v)
>         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);
> +               debugfs_print_log(seq, test_case->log);
>
> -       if (suite->log)
> -               seq_printf(seq, "%s", suite->log);
> +       debugfs_print_log(seq, suite->log);
>
>         seq_printf(seq, "%s %d %s\n",
>                    kunit_status_to_ok_not_ok(success), 1, suite->name);
> @@ -100,14 +101,53 @@ static const struct file_operations debugfs_results_fops = {
>         .release = debugfs_release,
>  };
>
> +static struct list_head *kunit_debugfs_alloc_log(void)
> +{
> +       struct list_head *log;
> +       struct kunit_log_frag *frag;
> +
> +       log = kzalloc(sizeof(*log), GFP_KERNEL);
> +       if (!log)
> +               return NULL;
> +
> +       INIT_LIST_HEAD(log);
> +
> +       frag = kmalloc(sizeof(*frag), GFP_KERNEL);
> +       if (!frag) {
> +               kfree(log);
> +               return NULL;
> +       }
> +
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, log);
> +
> +       return log;
> +}
> +
> +static void kunit_debugfs_free_log(struct list_head *log)
> +{
> +       struct kunit_log_frag *frag, *n;
> +
> +       if (!log)
> +               return;
> +
> +       list_for_each_entry_safe(frag, n, log, list) {
> +               list_del(&frag->list);
> +               kfree(frag);
> +       }
> +
> +       kfree(log);
> +}
> +
>  void kunit_debugfs_create_suite(struct kunit_suite *suite)
>  {
>         struct kunit_case *test_case;
>
>         /* Allocate logs before creating debugfs representation. */
> -       suite->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
> +       suite->log = kunit_debugfs_alloc_log();
> +
>         kunit_suite_for_each_test_case(suite, test_case)
> -               test_case->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
> +               test_case->log = kunit_debugfs_alloc_log();
>
>         suite->debugfs = debugfs_create_dir(suite->name, debugfs_rootdir);
>
> @@ -121,7 +161,8 @@ void kunit_debugfs_destroy_suite(struct kunit_suite *suite)
>         struct kunit_case *test_case;
>
>         debugfs_remove_recursive(suite->debugfs);
> -       kfree(suite->log);
> +       kunit_debugfs_free_log(suite->log);
> +
>         kunit_suite_for_each_test_case(suite, test_case)
> -               kfree(test_case->log);
> +               kunit_debugfs_free_log(test_case->log);
>  }
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index 83d8e90ca7a2..a199f83bac67 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -530,12 +530,37 @@ static struct kunit_suite kunit_resource_test_suite = {
>         .test_cases = kunit_resource_test_cases,
>  };
>
> +static char *get_concatenated_log(struct kunit *test, const struct list_head *log)
> +{
> +       struct kunit_log_frag *frag;
> +       size_t len = 0;
> +       char *p;

I wonder if we could change the name of p to be a bit more
descriptive. Maybe concat_log?

> +
> +       list_for_each_entry(frag, log, list)
> +               len += strlen(frag->buf);
> +
> +       len++; /* for terminating '\0' */
> +       p = kunit_kzalloc(test, len, GFP_KERNEL);
> +
> +       list_for_each_entry(frag, log, list)
> +               strlcat(p, frag->buf, len);
> +
> +       return p;
> +}
> +
>  static void kunit_log_test(struct kunit *test)
>  {
>         struct kunit_suite suite;
> +       struct kunit_log_frag *frag;
>
> -       suite.log = kunit_kzalloc(test, KUNIT_LOG_SIZE, GFP_KERNEL);
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
>         KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);

This section of the test is pretty dense. I would love to see at least
one comment in this section. Maybe it could be here and say something
like:
"/* Allocate, initialize, and then add the first fragment of log */"

> +       frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
> +       KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
> +       list_add_tail(&frag->list, suite.log);
>
>         kunit_log(KERN_INFO, test, "put this in log.");
>         kunit_log(KERN_INFO, test, "this too.");
> @@ -543,14 +568,17 @@ static void kunit_log_test(struct kunit *test)
>         kunit_log(KERN_INFO, &suite, "along with this.");
>
>  #ifdef CONFIG_KUNIT_DEBUGFS
> +       frag = list_first_entry(test->log, struct kunit_log_frag, list);
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(test->log, "put this in log."));
> +                                    strstr(frag->buf, "put this in log."));
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(test->log, "this too."));
> +                                    strstr(frag->buf, "this too."));
> +
> +       frag = list_first_entry(suite.log, struct kunit_log_frag, list);
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(suite.log, "add to suite log."));
> +                                    strstr(frag->buf, "add to suite log."));
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(suite.log, "along with this."));
> +                                    strstr(frag->buf, "along with this."));
>  #else
>         KUNIT_EXPECT_NULL(test, test->log);

This test passes when CONFIG_KUNIT_DEBUGFS=n while most of the other
tests are skipped. Should this test be skipped instead?

I'm assuming since the assert/expect statements at the beginning are
run even if CONFIG_KUNIT_DEBUGFS=n, this test should not be skipped
but I just wanted to check.

>  #endif
> @@ -558,11 +586,15 @@ static void kunit_log_test(struct kunit *test)
>
>  static void kunit_log_newline_test(struct kunit *test)
>  {
> +       struct kunit_log_frag *frag;
> +
>         kunit_info(test, "Add newline\n");
>         if (test->log) {

This is a small nit but I would prefer that the if statements to
decide whether CONFIG_KUNIT_DEBUGFS is enabled were uniform. So I
would prefer that we choose between if (test->log) and #ifdef
CONFIG_KUNIT_DEBUGFS. I think we originally chose to use if
(test->log) here to avoid the compile-time #ifdef.

> -               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"));
> +               frag = list_first_entry(test->log, struct kunit_log_frag, list);
> +               KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
> +                       "Missing log line, full log:\n%s",
> +                       get_concatenated_log(test, test->log));
> +               KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
>         } else {
>                 kunit_skip(test, "only useful when debugfs is enabled");
>         }
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 49698a168437..dfe51bc2b387 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -11,6 +11,7 @@
>  #include <kunit/test-bug.h>
>  #include <kunit/attributes.h>
>  #include <linux/kernel.h>
> +#include <linux/list.h>
>  #include <linux/module.h>
>  #include <linux/moduleparam.h>
>  #include <linux/panic.h>
> @@ -114,46 +115,66 @@ static void kunit_print_test_stats(struct kunit *test,
>   * already present.
>   * @log: The log to add the newline to.
>   */
> -static void kunit_log_newline(char *log)
> +static void kunit_log_newline(struct kunit_log_frag *frag)
>  {
>         int log_len, len_left;
>
> -       log_len = strlen(log);
> -       len_left = KUNIT_LOG_SIZE - log_len - 1;
> +       log_len = strlen(frag->buf);
> +       len_left = sizeof(frag->buf) - log_len - 1;
>
> -       if (log_len > 0 && log[log_len - 1] != '\n')
> -               strncat(log, "\n", len_left);
> +       if (log_len > 0 && frag->buf[log_len - 1] != '\n')
> +               strncat(frag->buf, "\n", len_left);
>  }
>
> -/*
> - * Append formatted message to log, size of which is limited to
> - * KUNIT_LOG_SIZE bytes (including null terminating byte).
> - */
> -void kunit_log_append(char *log, const char *fmt, ...)
> +static struct kunit_log_frag *kunit_log_extend(struct list_head *log)

I would love to see just a short comment describing kunit_log_extend
to prevent confusion with kunit_log_append.



> +{
> +       struct kunit_log_frag *frag;
> +
> +       frag = kmalloc(sizeof(*frag), GFP_KERNEL);
> +       if (!frag)
> +               return NULL;
> +
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, log);
> +
> +       return frag;
> +}
> +
> +/* Append formatted message to log, extending the log buffer if necessary. */
> +void kunit_log_append(struct list_head *log, const char *fmt, ...)
>  {
>         va_list args;
> +       struct kunit_log_frag *frag;
>         int len, log_len, len_left;
>
>         if (!log)
>                 return;
>
> -       log_len = strlen(log);
> -       len_left = KUNIT_LOG_SIZE - log_len - 1;
> -       if (len_left <= 0)
> -               return;
> +       frag = list_last_entry(log, struct kunit_log_frag, list);
> +       log_len = strlen(frag->buf);
> +       len_left = sizeof(frag->buf) - log_len - 1;
>
>         /* Evaluate length of line to add to log */
>         va_start(args, fmt);
>         len = vsnprintf(NULL, 0, fmt, args) + 1;
>         va_end(args);
>
> +       if (len > len_left) {
> +               frag = kunit_log_extend(log);
> +               if (!frag)
> +                       return;
> +
> +               len_left = sizeof(frag->buf) - 1;
> +               log_len = 0;
> +       }
> +
>         /* Print formatted line to the log */
>         va_start(args, fmt);
> -       vsnprintf(log + log_len, min(len, len_left), fmt, args);
> +       vsnprintf(frag->buf + 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);
> +       kunit_log_newline(frag);
>  }
>  EXPORT_SYMBOL_GPL(kunit_log_append);
>
> @@ -359,14 +380,18 @@ void __kunit_do_failed_assertion(struct kunit *test,
>  }
>  EXPORT_SYMBOL_GPL(__kunit_do_failed_assertion);
>
> -void kunit_init_test(struct kunit *test, const char *name, char *log)
> +void kunit_init_test(struct kunit *test, const char *name, struct list_head *log)
>  {
>         spin_lock_init(&test->lock);
>         INIT_LIST_HEAD(&test->resources);
>         test->name = name;
>         test->log = log;
> -       if (test->log)
> -               test->log[0] = '\0';
> +       if (test->log) {
> +               struct kunit_log_frag *frag = list_first_entry(test->log,
> +                                                              struct kunit_log_frag,
> +                                                              list);
> +               frag->buf[0] = '\0';
> +       }
>         test->status = KUNIT_SUCCESS;
>         test->status_comment[0] = '\0';
>  }
> --
> 2.30.2
>

Re: [PATCH v3 1/7] kunit: Replace fixed-size log with dynamically-extending buffer

[Richard Fitzgerald]

On 9/8/23 22:10, Rae Moar wrote:
> On Wed, Aug 9, 2023 at 11:54 AM Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> Re-implement the log buffer as a list of buffer fragments that can
>> be extended as the size of the log info grows.
>>
>> When using parameterization the test case can run many times and create
>> a large amount of log. It's not really practical to keep increasing the
>> size of the fixed buffer every time a test needs more space. And a big
>> fixed buffer wastes memory.
>>
>> The original char *log pointer is replaced by a pointer to a list of
>> struct kunit_log_frag, each containing a fixed-size buffer.
>>
>> kunit_log_append() now attempts to append to the last kunit_log_frag in
>> the list. If there isn't enough space it will append a new kunit_log_frag
>> to the list. This simple implementation does not attempt to completely
>> fill the buffer in every kunit_log_frag.
>>
>> The 'log' member of kunit_suite, kunit_test_case and kunit_suite must be a
>> pointer because the API of kunit_log() requires that is the same type in
>> all  three structs. As kunit.log is a pointer to the 'log' of the current
>> kunit_case, it must be a pointer in the other two structs.
>>
>> The existing kunit-test.c log tests have been updated to build against the
>> new fragmented log implementation. If the test fails the new function
>> get_concatenated_log() constructs a single contiguous string from the
>> log fragments so that the whole log can be emitted in the failure
>> message.
> 
> Hello!
> 
> All the tests now pass for me and this patch now looks good to me. I
> have tested it and it seems to be working well.
> 
> I just have a few nits below. But I am overall happy with this patch.
> 
> Reviewed-by: Rae Moar <rmoar@google.com>
> 
> -Rae
> 

...

>> +static char *get_concatenated_log(struct kunit *test, const struct list_head *log)
>> +{
>> +       struct kunit_log_frag *frag;
>> +       size_t len = 0;
>> +       char *p;
> 
> I wonder if we could change the name of p to be a bit more
> descriptive. Maybe concat_log?

I'll do that.

>> +
>> +       list_for_each_entry(frag, log, list)
>> +               len += strlen(frag->buf);
>> +
>> +       len++; /* for terminating '\0' */
>> +       p = kunit_kzalloc(test, len, GFP_KERNEL);
>> +
>> +       list_for_each_entry(frag, log, list)
>> +               strlcat(p, frag->buf, len);
>> +
>> +       return p;
>> +}
>> +
>>   static void kunit_log_test(struct kunit *test)
>>   {
>>          struct kunit_suite suite;
>> +       struct kunit_log_frag *frag;
>>
>> -       suite.log = kunit_kzalloc(test, KUNIT_LOG_SIZE, GFP_KERNEL);
>> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
>>          KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
>> +       INIT_LIST_HEAD(suite.log);
> 
> This section of the test is pretty dense. I would love to see at least
> one comment in this section. Maybe it could be here and say something
> like:
> "/* Allocate, initialize, and then add the first fragment of log */"

Good. You like comments. So do I.
But many people hate them so when I'm starting on a new subsystem I go
with however the existing code looks. And the bits of kunit I've looked
at are light on comments.

...

>> @@ -543,14 +568,17 @@ static void kunit_log_test(struct kunit *test)
>>          kunit_log(KERN_INFO, &suite, "along with this.");
>>
>>   #ifdef CONFIG_KUNIT_DEBUGFS
>> +       frag = list_first_entry(test->log, struct kunit_log_frag, list);
>>          KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
>> -                                    strstr(test->log, "put this in log."));
>> +                                    strstr(frag->buf, "put this in log."));
>>          KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
>> -                                    strstr(test->log, "this too."));
>> +                                    strstr(frag->buf, "this too."));
>> +
>> +       frag = list_first_entry(suite.log, struct kunit_log_frag, list);
>>          KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
>> -                                    strstr(suite.log, "add to suite log."));
>> +                                    strstr(frag->buf, "add to suite log."));
>>          KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
>> -                                    strstr(suite.log, "along with this."));
>> +                                    strstr(frag->buf, "along with this."));
>>   #else
>>          KUNIT_EXPECT_NULL(test, test->log);
> 
> This test passes when CONFIG_KUNIT_DEBUGFS=n while most of the other
> tests are skipped. Should this test be skipped instead?
> 
> I'm assuming since the assert/expect statements at the beginning are
> run even if CONFIG_KUNIT_DEBUGFS=n, this test should not be skipped
> but I just wanted to check.

That the existing code, which I didn't change.
I think the best thing here would be to move the fragment testing into a
new test case.

>>   #endif
>> @@ -558,11 +586,15 @@ static void kunit_log_test(struct kunit *test)
>>
>>   static void kunit_log_newline_test(struct kunit *test)
>>   {
>> +       struct kunit_log_frag *frag;
>> +
>>          kunit_info(test, "Add newline\n");
>>          if (test->log) {
> 
> This is a small nit but I would prefer that the if statements to
> decide whether CONFIG_KUNIT_DEBUGFS is enabled were uniform. So I
> would prefer that we choose between if (test->log) and #ifdef
> CONFIG_KUNIT_DEBUGFS. I think we originally chose to use if
> (test->log) here to avoid the compile-time #ifdef.

Actually the existing code did it both ways. The newline test used
if (test->log) - but this makes sense because it actually does testing
on test->log.

The original kunit_log_test() used #ifdef CONFIG_KUNIT_DEBUGFS. I based
my new functions on kunit_log_test(). But I can change them. Would you
prefer

	if (!test->log)
		skip

or
	if (!IS_ENABLED(CONFIG_KUNIT_DEBUGFS))
		skip

[PATCH v3 2/7] kunit: kunit-test: Add test cases for extending log buffer

[Richard Fitzgerald]

Add test cases for the dynamically-extending log buffer.

kunit_log_init_frag_test() tests that kunit_init_log_frag() correctly
initializes new struct kunit_log_frag.

kunit_log_extend_test_1() logs a series of numbered lines then tests
that the resulting log contains all the lines.

kunit_log_extend_test_2() logs a large number of lines of varying length
to create many fragments, then tests that all lines are present.

kunit_log_newline_test() has a new test to append a line that is exactly
the length of the available space in the current fragment and check that
the resulting log has a trailing '\n'.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 lib/kunit/kunit-test.c | 182 +++++++++++++++++++++++++++++++++++++++--
 1 file changed, 174 insertions(+), 8 deletions(-)

diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index a199f83bac67..c0ee33a8031e 100644
--- a/lib/kunit/kunit-test.c
+++ b/lib/kunit/kunit-test.c
@@ -7,6 +7,7 @@
  */
 #include <kunit/test.h>
 #include <kunit/test-bug.h>
+#include <linux/prandom.h>
 
 #include "try-catch-impl.h"
 
@@ -530,10 +531,12 @@ static struct kunit_suite kunit_resource_test_suite = {
 	.test_cases = kunit_resource_test_cases,
 };
 
-static char *get_concatenated_log(struct kunit *test, const struct list_head *log)
+static char *get_concatenated_log(struct kunit *test, const struct list_head *log,
+				  int *num_frags)
 {
 	struct kunit_log_frag *frag;
 	size_t len = 0;
+	int frag_count = 0;
 	char *p;
 
 	list_for_each_entry(frag, log, list)
@@ -542,24 +545,42 @@ static char *get_concatenated_log(struct kunit *test, const struct list_head *lo
 	len++; /* for terminating '\0' */
 	p = kunit_kzalloc(test, len, GFP_KERNEL);
 
-	list_for_each_entry(frag, log, list)
+	list_for_each_entry(frag, log, list) {
 		strlcat(p, frag->buf, len);
+		++frag_count;
+	}
+
+	if (num_frags)
+		*num_frags = frag_count;
 
 	return p;
 }
 
-static void kunit_log_test(struct kunit *test)
+static void kunit_log_init_frag_test(struct kunit *test)
 {
-	struct kunit_suite suite;
 	struct kunit_log_frag *frag;
 
-	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
-	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
-	INIT_LIST_HEAD(suite.log);
 	frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
 	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	memset(frag, 0x5a, sizeof(*frag));
+
 	kunit_init_log_frag(frag);
 	KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
+	KUNIT_EXPECT_TRUE(test, list_is_first(&frag->list, &frag->list));
+	KUNIT_EXPECT_TRUE(test, list_is_last(&frag->list, &frag->list));
+}
+
+static void kunit_log_test(struct kunit *test)
+{
+	struct kunit_suite suite;
+	struct kunit_log_frag *frag;
+
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
 	list_add_tail(&frag->list, suite.log);
 
 	kunit_log(KERN_INFO, test, "put this in log.");
@@ -586,23 +607,168 @@ static void kunit_log_test(struct kunit *test)
 
 static void kunit_log_newline_test(struct kunit *test)
 {
+	struct kunit_suite suite;
 	struct kunit_log_frag *frag;
+	char *p;
 
 	kunit_info(test, "Add newline\n");
 	if (test->log) {
 		frag = list_first_entry(test->log, struct kunit_log_frag, list);
 		KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
 			"Missing log line, full log:\n%s",
-			get_concatenated_log(test, test->log));
+			get_concatenated_log(test, test->log, NULL));
 		KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
+
+		suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+		INIT_LIST_HEAD(suite.log);
+		frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+		kunit_init_log_frag(frag);
+		list_add_tail(&frag->list, suite.log);
+
+		/* String that exactly fills fragment leaving no room for \n */
+		memset(frag->buf, 0, sizeof(frag->buf));
+		memset(frag->buf, 'x', sizeof(frag->buf) - 9);
+		kunit_log_append(suite.log, "12345678");
+		p = get_concatenated_log(test, suite.log, NULL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+		KUNIT_EXPECT_NOT_NULL_MSG(test, strstr(p, "x12345678\n"),
+			"Newline not appended when fragment is full. Log is:\n'%s'", p);
 	} else {
 		kunit_skip(test, "only useful when debugfs is enabled");
 	}
 }
 
+static void kunit_log_extend_test_1(struct kunit *test)
+{
+#ifdef CONFIG_KUNIT_DEBUGFS
+	struct kunit_suite suite;
+	struct kunit_log_frag *frag;
+	char line[60];
+	char *p, *pn;
+	size_t len, n;
+	int num_lines, num_frags, i;
+
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, suite.log);
+
+	i = 0;
+	len = 0;
+	do {
+		n = snprintf(line, sizeof(line),
+			     "The quick brown fox jumps over the lazy penguin %d\n", i);
+		KUNIT_ASSERT_LT(test, n, sizeof(line));
+		kunit_log_append(suite.log, line);
+		++i;
+		len += n;
+	}  while (len < (sizeof(frag->buf) * 30));
+	num_lines = i;
+
+	p = get_concatenated_log(test, suite.log, &num_frags);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+	KUNIT_EXPECT_GT(test, num_frags, 1);
+
+	kunit_info(test, "num lines:%d num_frags:%d total len:%zu\n",
+		   num_lines, num_frags, strlen(p));
+
+	i = 0;
+	while ((pn = strchr(p, '\n')) != NULL) {
+		*pn = '\0';
+		snprintf(line, sizeof(line),
+			 "The quick brown fox jumps over the lazy penguin %d", i);
+		KUNIT_EXPECT_STREQ(test, p, line);
+		p = pn + 1;
+		++i;
+	}
+	KUNIT_EXPECT_EQ(test, i, num_lines);
+#else
+	kunit_skip(test, "only useful when debugfs is enabled");
+#endif
+}
+
+static void kunit_log_extend_test_2(struct kunit *test)
+{
+#ifdef CONFIG_KUNIT_DEBUGFS
+	struct kunit_suite suite;
+	struct kunit_log_frag *frag;
+	struct rnd_state rnd;
+	char line[101];
+	char *p, *pn;
+	size_t len;
+	int num_lines, num_frags, n, i;
+
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, suite.log);
+
+	/* Build log line of varying content */
+	line[0] = '\0';
+	i = 0;
+	do {
+		char tmp[9];
+
+		snprintf(tmp, sizeof(tmp), "%x", i++);
+		len = strlcat(line, tmp, sizeof(line));
+	} while (len < sizeof(line) - 1);
+
+	/*
+	 * Log lines of different lengths until we have created
+	 * many fragments.
+	 * The "randomness" must be repeatable.
+	 */
+	prandom_seed_state(&rnd, 3141592653589793238ULL);
+	i = 0;
+	len = 0;
+	num_lines = 0;
+	do {
+		kunit_log_append(suite.log, "%s\n", &line[i]);
+		len += sizeof(line) - i;
+		num_lines++;
+		i = prandom_u32_state(&rnd) % (sizeof(line) - 1);
+	} while (len < (sizeof(frag->buf) * 30));
+
+	/* There must be more than one buffer fragment now */
+	KUNIT_EXPECT_FALSE(test, list_is_singular(suite.log));
+
+	p = get_concatenated_log(test, suite.log, &num_frags);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+	KUNIT_EXPECT_GT(test, num_frags, 1);
+
+	kunit_info(test, "num lines:%d num_frags:%d total len:%zu\n",
+		   num_lines, num_frags, strlen(p));
+
+	prandom_seed_state(&rnd, 3141592653589793238ULL);
+	i = 0;
+	n = 0;
+	while ((pn = strchr(p, '\n')) != NULL) {
+		*pn = '\0';
+		KUNIT_EXPECT_STREQ(test, p, &line[i]);
+		p = pn + 1;
+		n++;
+		i = prandom_u32_state(&rnd) % (sizeof(line) - 1);
+	}
+	KUNIT_EXPECT_EQ_MSG(test, n, num_lines, "Not enough lines.");
+#else
+	kunit_skip(test, "only useful when debugfs is enabled");
+#endif
+}
+
 static struct kunit_case kunit_log_test_cases[] = {
+	KUNIT_CASE(kunit_log_init_frag_test),
 	KUNIT_CASE(kunit_log_test),
 	KUNIT_CASE(kunit_log_newline_test),
+	KUNIT_CASE(kunit_log_extend_test_1),
+	KUNIT_CASE(kunit_log_extend_test_2),
 	{}
 };
 
-- 
2.30.2

Re: [PATCH v3 2/7] kunit: kunit-test: Add test cases for extending log buffer

[Rae Moar]

On Wed, Aug 9, 2023 at 11:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Add test cases for the dynamically-extending log buffer.
>
> kunit_log_init_frag_test() tests that kunit_init_log_frag() correctly
> initializes new struct kunit_log_frag.
>
> kunit_log_extend_test_1() logs a series of numbered lines then tests
> that the resulting log contains all the lines.
>
> kunit_log_extend_test_2() logs a large number of lines of varying length
> to create many fragments, then tests that all lines are present.
>
> kunit_log_newline_test() has a new test to append a line that is exactly
> the length of the available space in the current fragment and check that
> the resulting log has a trailing '\n'.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>

Hello!

These tests now pass for me. Thanks!

I do have a few comments below mostly regarding comments and a few
clarifying questions.

-Rae

> ---
>  lib/kunit/kunit-test.c | 182 +++++++++++++++++++++++++++++++++++++++--
>  1 file changed, 174 insertions(+), 8 deletions(-)
>
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index a199f83bac67..c0ee33a8031e 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -7,6 +7,7 @@
>   */
>  #include <kunit/test.h>
>  #include <kunit/test-bug.h>
> +#include <linux/prandom.h>
>
>  #include "try-catch-impl.h"
>
> @@ -530,10 +531,12 @@ static struct kunit_suite kunit_resource_test_suite = {
>         .test_cases = kunit_resource_test_cases,
>  };
>
> -static char *get_concatenated_log(struct kunit *test, const struct list_head *log)
> +static char *get_concatenated_log(struct kunit *test, const struct list_head *log,
> +                                 int *num_frags)
>  {
>         struct kunit_log_frag *frag;
>         size_t len = 0;
> +       int frag_count = 0;
>         char *p;
>
>         list_for_each_entry(frag, log, list)
> @@ -542,24 +545,42 @@ static char *get_concatenated_log(struct kunit *test, const struct list_head *lo
>         len++; /* for terminating '\0' */
>         p = kunit_kzalloc(test, len, GFP_KERNEL);
>
> -       list_for_each_entry(frag, log, list)
> +       list_for_each_entry(frag, log, list) {
>                 strlcat(p, frag->buf, len);
> +               ++frag_count;
> +       }
> +
> +       if (num_frags)
> +               *num_frags = frag_count;
>
>         return p;
>  }
>
> -static void kunit_log_test(struct kunit *test)
> +static void kunit_log_init_frag_test(struct kunit *test)
>  {
> -       struct kunit_suite suite;
>         struct kunit_log_frag *frag;
>
> -       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> -       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> -       INIT_LIST_HEAD(suite.log);
>         frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
>         KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       memset(frag, 0x5a, sizeof(*frag));
> +

Why is the fragment getting filled here with memset? Should this be
tested? Feel free to let me know, I'm just uncertain.

>         kunit_init_log_frag(frag);
>         KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
> +       KUNIT_EXPECT_TRUE(test, list_is_first(&frag->list, &frag->list));
> +       KUNIT_EXPECT_TRUE(test, list_is_last(&frag->list, &frag->list));
> +}
> +
> +static void kunit_log_test(struct kunit *test)
> +{
> +       struct kunit_suite suite;
> +       struct kunit_log_frag *frag;
> +
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);
> +       frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
>         list_add_tail(&frag->list, suite.log);
>
>         kunit_log(KERN_INFO, test, "put this in log.");
> @@ -586,23 +607,168 @@ static void kunit_log_test(struct kunit *test)
>
>  static void kunit_log_newline_test(struct kunit *test)
>  {
> +       struct kunit_suite suite;
>         struct kunit_log_frag *frag;
> +       char *p;

Similar to last email, could we change p to be a more descriptive name
such as concat_log?

>
>         kunit_info(test, "Add newline\n");
>         if (test->log) {
>                 frag = list_first_entry(test->log, struct kunit_log_frag, list);
>                 KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
>                         "Missing log line, full log:\n%s",
> -                       get_concatenated_log(test, test->log));
> +                       get_concatenated_log(test, test->log, NULL));
>                 KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
> +

Should this section of kunit_log_newline_test be separated into a new
test? This test seems a bit long and seems to have two distinct
sections?

> +               suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +               INIT_LIST_HEAD(suite.log);

I would love to see a comment here to explain and break up this
section similar to the comment from the previous email.

> +               frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +               kunit_init_log_frag(frag);
> +               list_add_tail(&frag->list, suite.log);
> +
> +               /* String that exactly fills fragment leaving no room for \n */
> +               memset(frag->buf, 0, sizeof(frag->buf));
> +               memset(frag->buf, 'x', sizeof(frag->buf) - 9);
> +               kunit_log_append(suite.log, "12345678");
> +               p = get_concatenated_log(test, suite.log, NULL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +               KUNIT_EXPECT_NOT_NULL_MSG(test, strstr(p, "x12345678\n"),
> +                       "Newline not appended when fragment is full. Log is:\n'%s'", p);
>         } else {
>                 kunit_skip(test, "only useful when debugfs is enabled");
>         }
>  }
>
> +static void kunit_log_extend_test_1(struct kunit *test)

In general, I would really like to see more comments in the next two
tests describing the test behavior. I would prefer a comment for each
of the while/do-while loops below. I just found the behavior to be
slightly confusing to understand without comments (although I do
appreciate the comments that are in kunit_log_extend_test_2).

Also, I really appreciate how detailed these tests are.

Another potential idea is to rename these two tests to be
kunit_log_extend_test() and kunit_log_rand_extend_test() instead to be
more descriptive?

> +{
> +#ifdef CONFIG_KUNIT_DEBUGFS
> +       struct kunit_suite suite;
> +       struct kunit_log_frag *frag;
> +       char line[60];
> +       char *p, *pn;

Similar to before, could we change p and pn to be slightly more
descriptive names? Maybe concat_log and newline_ptr or newline_log or
newline_char?

> +       size_t len, n;
> +       int num_lines, num_frags, i;
> +
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);
> +       frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, suite.log);
> +
> +       i = 0;
> +       len = 0;
> +       do {
> +               n = snprintf(line, sizeof(line),
> +                            "The quick brown fox jumps over the lazy penguin %d\n", i);
> +               KUNIT_ASSERT_LT(test, n, sizeof(line));
> +               kunit_log_append(suite.log, line);
> +               ++i;
> +               len += n;
> +       }  while (len < (sizeof(frag->buf) * 30));

Are we trying to restrict the num_frags to less than 30? And then we
could check that with a KUNIT_EXPECT? Currently, the num_frags are
just above 30. That is ok too. I just was wondering if this was
intentional? (Same as kunit_log_extend_test_2)

> +       num_lines = i;
> +
> +       p = get_concatenated_log(test, suite.log, &num_frags);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +       KUNIT_EXPECT_GT(test, num_frags, 1);
> +
> +       kunit_info(test, "num lines:%d num_frags:%d total len:%zu\n",
> +                  num_lines, num_frags, strlen(p));
> +
> +       i = 0;
> +       while ((pn = strchr(p, '\n')) != NULL) {
> +               *pn = '\0';
> +               snprintf(line, sizeof(line),
> +                        "The quick brown fox jumps over the lazy penguin %d", i);
> +               KUNIT_EXPECT_STREQ(test, p, line);
> +               p = pn + 1;
> +               ++i;
> +       }
> +       KUNIT_EXPECT_EQ(test, i, num_lines);
> +#else
> +       kunit_skip(test, "only useful when debugfs is enabled");
> +#endif
> +}
> +
> +static void kunit_log_extend_test_2(struct kunit *test)
> +{
> +#ifdef CONFIG_KUNIT_DEBUGFS
> +       struct kunit_suite suite;
> +       struct kunit_log_frag *frag;
> +       struct rnd_state rnd;
> +       char line[101];
> +       char *p, *pn;

Similar to above, could p and pn be renamed to be more descriptive?

> +       size_t len;
> +       int num_lines, num_frags, n, i;
> +
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);
> +       frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, suite.log);
> +
> +       /* Build log line of varying content */
> +       line[0] = '\0';
> +       i = 0;
> +       do {
> +               char tmp[9];
> +
> +               snprintf(tmp, sizeof(tmp), "%x", i++);
> +               len = strlcat(line, tmp, sizeof(line));
> +       } while (len < sizeof(line) - 1);

Could there be an expectation statement here to check the line has
been properly filled. Maybe checking the length?

> +
> +       /*
> +        * Log lines of different lengths until we have created
> +        * many fragments.
> +        * The "randomness" must be repeatable.
> +        */
> +       prandom_seed_state(&rnd, 3141592653589793238ULL);
> +       i = 0;
> +       len = 0;
> +       num_lines = 0;
> +       do {
> +               kunit_log_append(suite.log, "%s\n", &line[i]);
> +               len += sizeof(line) - i;
> +               num_lines++;
> +               i = prandom_u32_state(&rnd) % (sizeof(line) - 1);
> +       } while (len < (sizeof(frag->buf) * 30));
> +
> +       /* There must be more than one buffer fragment now */
> +       KUNIT_EXPECT_FALSE(test, list_is_singular(suite.log));
> +
> +       p = get_concatenated_log(test, suite.log, &num_frags);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +       KUNIT_EXPECT_GT(test, num_frags, 1);
> +
> +       kunit_info(test, "num lines:%d num_frags:%d total len:%zu\n",
> +                  num_lines, num_frags, strlen(p));
> +
> +       prandom_seed_state(&rnd, 3141592653589793238ULL);
> +       i = 0;
> +       n = 0;
> +       while ((pn = strchr(p, '\n')) != NULL) {
> +               *pn = '\0';
> +               KUNIT_EXPECT_STREQ(test, p, &line[i]);
> +               p = pn + 1;
> +               n++;
> +               i = prandom_u32_state(&rnd) % (sizeof(line) - 1);
> +       }
> +       KUNIT_EXPECT_EQ_MSG(test, n, num_lines, "Not enough lines.");

Is it possible for this to be too many lines instead? Should this
comment instead be "Unexpected number of lines". Also could we have a
similar message for the test above for this expectation regarding the
number of lines.


> +#else
> +       kunit_skip(test, "only useful when debugfs is enabled");
> +#endif
> +}
> +
>  static struct kunit_case kunit_log_test_cases[] = {
> +       KUNIT_CASE(kunit_log_init_frag_test),
>         KUNIT_CASE(kunit_log_test),
>         KUNIT_CASE(kunit_log_newline_test),
> +       KUNIT_CASE(kunit_log_extend_test_1),
> +       KUNIT_CASE(kunit_log_extend_test_2),
>         {}
>  };
>
> --
> 2.30.2
>

Re: [PATCH v3 2/7] kunit: kunit-test: Add test cases for extending log buffer

[Richard Fitzgerald]

On 9/8/23 22:10, Rae Moar wrote:
> On Wed, Aug 9, 2023 at 11:54 AM Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> Add test cases for the dynamically-extending log buffer.
>>
>> kunit_log_init_frag_test() tests that kunit_init_log_frag() correctly
>> initializes new struct kunit_log_frag.
>>
>> kunit_log_extend_test_1() logs a series of numbered lines then tests
>> that the resulting log contains all the lines.
>>
>> kunit_log_extend_test_2() logs a large number of lines of varying length
>> to create many fragments, then tests that all lines are present.
>>
>> kunit_log_newline_test() has a new test to append a line that is exactly
>> the length of the available space in the current fragment and check that
>> the resulting log has a trailing '\n'.
>>
>> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> 
> Hello!
> 
> These tests now pass for me. Thanks!
> 
> I do have a few comments below mostly regarding comments and a few
> clarifying questions.
> 
> -Rae

...

>> +static void kunit_log_init_frag_test(struct kunit *test)
>>   {
>> -       struct kunit_suite suite;
>>          struct kunit_log_frag *frag;
>>
>> -       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
>> -       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
>> -       INIT_LIST_HEAD(suite.log);
>>          frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
>>          KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
>> +       memset(frag, 0x5a, sizeof(*frag));
>> +
> 
> Why is the fragment getting filled here with memset? Should this be
> tested? Feel free to let me know, I'm just uncertain.

I'll add a comment in V4. It's to prove that kunit_init_log_frag()
really did change something. kzalloc() is no good for this because we
want to see that kunit_log_frag() zeroed buf[0].

...

>>          kunit_info(test, "Add newline\n");
>>          if (test->log) {
>>                  frag = list_first_entry(test->log, struct kunit_log_frag, list);
>>                  KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
>>                          "Missing log line, full log:\n%s",
>> -                       get_concatenated_log(test, test->log));
>> +                       get_concatenated_log(test, test->log, NULL));
>>                  KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
>> +
> 
> Should this section of kunit_log_newline_test be separated into a new
> test? This test seems a bit long and seems to have two distinct
> sections?

Yes, it makes sense to add a separate test case for when newlines cause
the log to extend.

...

> Another potential idea is to rename these two tests to be
> kunit_log_extend_test() and kunit_log_rand_extend_test() instead to be
> more descriptive?

TBH I had trouble thinking of a short description. But I'll spend some
time thinking about naming.

...

>> +       do {
>> +               n = snprintf(line, sizeof(line),
>> +                            "The quick brown fox jumps over the lazy penguin %d\n", i);
>> +               KUNIT_ASSERT_LT(test, n, sizeof(line));
>> +               kunit_log_append(suite.log, line);
>> +               ++i;
>> +               len += n;
>> +       }  while (len < (sizeof(frag->buf) * 30));
> 
> Are we trying to restrict the num_frags to less than 30? And then we
> could check that with a KUNIT_EXPECT? Currently, the num_frags are
> just above 30. That is ok too. I just was wondering if this was
> intentional? (Same as kunit_log_extend_test_2)

I'll comment on this in V4.
It's just trying to create "a lot" of data without assuming exactly
how kunit_log_append() breaks up the lines across fragments. I don't
want to have to keep changing this code if the fragmenting algorithm
changes slightly. So the idea is to generate "about 30" buffers worth.
I don't mind if it's a bit more, or a bit less. It's done this way,
instead of just counting how many fragments were created, to prevent
getting into an infinite loop if for some reason kunit_log_append()
fails to add fragments.

...

>> +       /* Build log line of varying content */
>> +       line[0] = '\0';
>> +       i = 0;
>> +       do {
>> +               char tmp[9];
>> +
>> +               snprintf(tmp, sizeof(tmp), "%x", i++);
>> +               len = strlcat(line, tmp, sizeof(line));
>> +       } while (len < sizeof(line) - 1);
> 
> Could there be an expectation statement here to check the line has
> been properly filled. Maybe checking the length?

Yes

>> +       prandom_seed_state(&rnd, 3141592653589793238ULL);
>> +       i = 0;
>> +       n = 0;
>> +       while ((pn = strchr(p, '\n')) != NULL) {
>> +               *pn = '\0';
>> +               KUNIT_EXPECT_STREQ(test, p, &line[i]);
>> +               p = pn + 1;
>> +               n++;
>> +               i = prandom_u32_state(&rnd) % (sizeof(line) - 1);
>> +       }
>> +       KUNIT_EXPECT_EQ_MSG(test, n, num_lines, "Not enough lines.");
> 
> Is it possible for this to be too many lines instead? Should this
> comment instead be "Unexpected number of lines". Also could we have a
> similar message for the test above for this expectation regarding the
> number of lines.

Fair point. It's only found that the number of lines is wrong, it
could be less or more.

[PATCH v3 3/7] kunit: Handle logging of lines longer than the fragment buffer size

[Richard Fitzgerald]

Add handling to kunit_log_append() for log messages that are longer than
a single buffer fragment.

The initial implementation of fragmented buffers did not change the logic
of the original kunit_log_append(). A consequence was that it still had
the original assumption that a log line will fit into one buffer.

This patch checks for log messages that are larger than one fragment
buffer. In that case, kvasprintf() is used to format it into a temporary
buffer and that content is then split across as many fragments as
necessary.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 61 insertions(+), 4 deletions(-)

diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index dfe51bc2b387..28d0048d6171 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
 	return frag;
 }
 
+static void kunit_log_append_string(struct list_head *log, const char *src)
+{
+	struct kunit_log_frag *frag, *new_frag;
+	int log_len, bytes_left;
+	ssize_t written;
+	char *p;
+
+	frag = list_last_entry(log, struct kunit_log_frag, list);
+	log_len = strlen(frag->buf);
+	bytes_left = sizeof(frag->buf) - log_len;
+
+	written = strscpy(frag->buf + log_len, src, bytes_left);
+	if (written != -E2BIG)
+		goto newline;
+
+	src += bytes_left - 1;
+	do {
+		new_frag = kunit_log_extend(log);
+		if (!new_frag)
+			goto newline;
+
+		frag = new_frag;
+		written = strscpy(frag->buf, src, sizeof(frag->buf));
+		src += sizeof(frag->buf) - 1;
+	} while (written == -E2BIG);
+
+newline:
+	if (written == -E2BIG)
+		written = strlen(frag->buf);
+
+	p = &frag->buf[written - 1];
+	if (*p != '\n') {
+		if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) {
+			frag = kunit_log_extend(log);
+			if (!frag) {
+				*p = '\n';
+				return;
+			}
+
+			frag->buf[0] = '\n';
+			frag->buf[1] = '\0';
+		}
+	}
+}
+
 /* Append formatted message to log, extending the log buffer if necessary. */
 void kunit_log_append(struct list_head *log, const char *fmt, ...)
 {
 	va_list args;
 	struct kunit_log_frag *frag;
 	int len, log_len, len_left;
+	char *tmp = NULL;
 
 	if (!log)
 		return;
 
-	frag = list_last_entry(log, struct kunit_log_frag, list);
-	log_len = strlen(frag->buf);
-	len_left = sizeof(frag->buf) - log_len - 1;
-
 	/* Evaluate length of line to add to log */
 	va_start(args, fmt);
 	len = vsnprintf(NULL, 0, fmt, args) + 1;
 	va_end(args);
 
+	if (len > sizeof(frag->buf) - 1) {
+		va_start(args, fmt);
+		tmp = kvasprintf(GFP_KERNEL, fmt, args);
+		va_end(args);
+
+		kunit_log_append_string(log, tmp);
+		kfree(tmp);
+
+		return;
+	}
+
+	frag = list_last_entry(log, struct kunit_log_frag, list);
+	log_len = strlen(frag->buf);
+	len_left = sizeof(frag->buf) - log_len - 1;
+
 	if (len > len_left) {
 		frag = kunit_log_extend(log);
 		if (!frag)
-- 
2.30.2

Re: [PATCH v3 3/7] kunit: Handle logging of lines longer than the fragment buffer size

[David Gow]

On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Add handling to kunit_log_append() for log messages that are longer than
> a single buffer fragment.
>
> The initial implementation of fragmented buffers did not change the logic
> of the original kunit_log_append(). A consequence was that it still had
> the original assumption that a log line will fit into one buffer.
>
> This patch checks for log messages that are larger than one fragment
> buffer. In that case, kvasprintf() is used to format it into a temporary
> buffer and that content is then split across as many fragments as
> necessary.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> ---

I think this looks good (and is a long-overdue addition to the logging
functionality).

One thought I have (and I'm kicking myself for not thinking of it
earlier) is that this is starting to get very similar to the "string
stream" functionality in lib/kunit/string-stream.{h,c}. Now, I
actually think this implementation is much more efficient (using
larger fragments, whereas the string stream uses variable-sized ones).
Particularly since there are a lot of cases where string streams are
created, converted to a string, and then logged, there's almost
certainly a bunch of redundant work being done here.

My gut feeling is that we should stick with this as-is, and maybe try
to either work out some better integration between string streams and
logging (to avoid that extra string allocation) or find some way of
combining them.

Regardless, this seems good as-is to me. There are some minor comments
below, but nothing disastrous. I'll let Rae have a look over the
various strscpy and strlcat calls, though, as while I did check them
carefully (and KASAN hasn't complained), it's always best to have as
many eyes on C string code as possible. :-)

But in my eyes, this is
Reviewed-by: David Gow <davidgow@google.com>

Cheers,
-- David

>  lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++---
>  1 file changed, 61 insertions(+), 4 deletions(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index dfe51bc2b387..28d0048d6171 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
>         return frag;
>  }
>
> +static void kunit_log_append_string(struct list_head *log, const char *src)
> +{
> +       struct kunit_log_frag *frag, *new_frag;
> +       int log_len, bytes_left;
> +       ssize_t written;
> +       char *p;
> +
> +       frag = list_last_entry(log, struct kunit_log_frag, list);
> +       log_len = strlen(frag->buf);
> +       bytes_left = sizeof(frag->buf) - log_len;
> +
> +       written = strscpy(frag->buf + log_len, src, bytes_left);
> +       if (written != -E2BIG)
> +               goto newline;
> +
> +       src += bytes_left - 1;
> +       do {
> +               new_frag = kunit_log_extend(log);
> +               if (!new_frag)
> +                       goto newline;
> +
> +               frag = new_frag;
> +               written = strscpy(frag->buf, src, sizeof(frag->buf));
> +               src += sizeof(frag->buf) - 1;
> +       } while (written == -E2BIG);
> +
> +newline:
> +       if (written == -E2BIG)

I think that this can only be true if kunit_log_extend() fails. If the
do/while loop ends naturally, then written != -E2BIG, as is the case
with the strscpy goto above.

Do you think it's cleaner to move the 'written = strlen(frag->buf)
into the if (!new_frag) statement within the loop?

> +               written = strlen(frag->buf);
> +
> +       p = &frag->buf[written - 1];
> +       if (*p != '\n') {
> +               if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) {
> +                       frag = kunit_log_extend(log);
> +                       if (!frag) {

A comment here could be useful. Something like "If we can't extend the
log to add a newline, truncate the last message".

> +                               *p = '\n';
> +                               return;
> +                       }
> +
> +                       frag->buf[0] = '\n';
> +                       frag->buf[1] = '\0';
> +               }
> +       }
> +}
> +
>  /* Append formatted message to log, extending the log buffer if necessary. */
>  void kunit_log_append(struct list_head *log, const char *fmt, ...)
>  {
>         va_list args;
>         struct kunit_log_frag *frag;
>         int len, log_len, len_left;
> +       char *tmp = NULL;
>
>         if (!log)
>                 return;
>
> -       frag = list_last_entry(log, struct kunit_log_frag, list);
> -       log_len = strlen(frag->buf);
> -       len_left = sizeof(frag->buf) - log_len - 1;
> -
>         /* Evaluate length of line to add to log */
>         va_start(args, fmt);
>         len = vsnprintf(NULL, 0, fmt, args) + 1;
>         va_end(args);
>
> +       if (len > sizeof(frag->buf) - 1) {
> +               va_start(args, fmt);
> +               tmp = kvasprintf(GFP_KERNEL, fmt, args);
> +               va_end(args);
> +

Should we handle the case where kvasprintf() fails here and drop the
log message?


> +               kunit_log_append_string(log, tmp);
> +               kfree(tmp);
> +
> +               return;
> +       }
> +
> +       frag = list_last_entry(log, struct kunit_log_frag, list);
> +       log_len = strlen(frag->buf);
> +       len_left = sizeof(frag->buf) - log_len - 1;
> +
>         if (len > len_left) {
>                 frag = kunit_log_extend(log);
>                 if (!frag)
> --
> 2.30.2
>

Re: [PATCH v3 3/7] kunit: Handle logging of lines longer than the fragment buffer size

[Richard Fitzgerald]

On 10/8/23 15:38, David Gow wrote:
> On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> Add handling to kunit_log_append() for log messages that are longer than
>> a single buffer fragment.
>>
>> The initial implementation of fragmented buffers did not change the logic
>> of the original kunit_log_append(). A consequence was that it still had
>> the original assumption that a log line will fit into one buffer.
>>
>> This patch checks for log messages that are larger than one fragment
>> buffer. In that case, kvasprintf() is used to format it into a temporary
>> buffer and that content is then split across as many fragments as
>> necessary.
>>
>> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
>> ---
> 
> I think this looks good (and is a long-overdue addition to the logging
> functionality).
> 
> One thought I have (and I'm kicking myself for not thinking of it
> earlier) is that this is starting to get very similar to the "string
> stream" functionality in lib/kunit/string-stream.{h,c}. Now, I
> actually think this implementation is much more efficient (using
> larger fragments, whereas the string stream uses variable-sized ones).
> Particularly since there are a lot of cases where string streams are
> created, converted to a string, and then logged, there's almost
> certainly a bunch of redundant work being done here.
>
> My gut feeling is that we should stick with this as-is, and maybe try
> to either work out some better integration between string streams and
> logging (to avoid that extra string allocation) or find some way of
> combining them.
>

I completely failed to notice string_stream. I could re-implement this
to use string_stream. I wonder whether appending newlines gets
a bit inefficient with the current string_stream implementation.
Could add newline support to string_stream and alloc one extra byte for
each fragment just in case we need to add a newline.

The string_stream implementation would waste a lot a memory if you log
many short lines. My current code wastes memory if you log lots of lines
that don't fit in available space in the current fragment - though it's
simple to shuffle the formatted string backwards to fill up the previous
fragment (I just haven't done that yet).

Re: [PATCH v3 3/7] kunit: Handle logging of lines longer than the fragment buffer size

[David Gow]

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

On Thu, 10 Aug 2023 at 23:09, Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> On 10/8/23 15:38, David Gow wrote:
> > On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
> > <rf@opensource.cirrus.com> wrote:
> >>
> >> Add handling to kunit_log_append() for log messages that are longer than
> >> a single buffer fragment.
> >>
> >> The initial implementation of fragmented buffers did not change the logic
> >> of the original kunit_log_append(). A consequence was that it still had
> >> the original assumption that a log line will fit into one buffer.
> >>
> >> This patch checks for log messages that are larger than one fragment
> >> buffer. In that case, kvasprintf() is used to format it into a temporary
> >> buffer and that content is then split across as many fragments as
> >> necessary.
> >>
> >> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> >> ---
> >
> > I think this looks good (and is a long-overdue addition to the logging
> > functionality).
> >
> > One thought I have (and I'm kicking myself for not thinking of it
> > earlier) is that this is starting to get very similar to the "string
> > stream" functionality in lib/kunit/string-stream.{h,c}. Now, I
> > actually think this implementation is much more efficient (using
> > larger fragments, whereas the string stream uses variable-sized ones).
> > Particularly since there are a lot of cases where string streams are
> > created, converted to a string, and then logged, there's almost
> > certainly a bunch of redundant work being done here.
> >
> > My gut feeling is that we should stick with this as-is, and maybe try
> > to either work out some better integration between string streams and
> > logging (to avoid that extra string allocation) or find some way of
> > combining them.
> >
>
> I completely failed to notice string_stream. I could re-implement this
> to use string_stream. I wonder whether appending newlines gets
> a bit inefficient with the current string_stream implementation.
> Could add newline support to string_stream and alloc one extra byte for
> each fragment just in case we need to add a newline.
>
> The string_stream implementation would waste a lot a memory if you log
> many short lines. My current code wastes memory if you log lots of lines
> that don't fit in available space in the current fragment - though it's
> simple to shuffle the formatted string backwards to fill up the previous
> fragment (I just haven't done that yet).

Yeah: I think your implementation here is overall better than the
string_stream one. string_stream might handle concurrency a bit
better, which would be nice to have as people start wanting to try
multithreaded tests.

I think the ideal solution is:
- Update string_stream to basically use this implementation.
- Update the logging code to then use this via the string_stream API
(probably with some tweaks to handle newlines)
- Optimize the string_stream append implementation to not create a
temporary string, as string streams are written to logs often. (If you
were prepared to allow string stream fragments to have variable
lengths, and do some ownership shenanigans, this could even become
O(1), though I suspect it's not worth the added complexity.)

That being said, I don't think we'd need to land all of that at once.
Even if we ported to the suboptimal string_stream API now (which would
still gain us the extensible log and some concurrency support), and
optimized string_stream later if it turned out to be tricky, that'd be
fine. (I wouldn't want to hold this up if changing string_stream was
regressing the other code which uses it, for example.)

How does that sound?

-- David

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

Re: [PATCH v3 3/7] kunit: Handle logging of lines longer than the fragment buffer size

[Rae Moar]

On Thu, Aug 10, 2023 at 9:38 AM David Gow <davidgow@google.com> wrote:
>
> On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
> >
> > Add handling to kunit_log_append() for log messages that are longer than
> > a single buffer fragment.
> >
> > The initial implementation of fragmented buffers did not change the logic
> > of the original kunit_log_append(). A consequence was that it still had
> > the original assumption that a log line will fit into one buffer.
> >
> > This patch checks for log messages that are larger than one fragment
> > buffer. In that case, kvasprintf() is used to format it into a temporary
> > buffer and that content is then split across as many fragments as
> > necessary.
> >
> > Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> > ---
>
> I think this looks good (and is a long-overdue addition to the logging
> functionality).
>
> One thought I have (and I'm kicking myself for not thinking of it
> earlier) is that this is starting to get very similar to the "string
> stream" functionality in lib/kunit/string-stream.{h,c}. Now, I
> actually think this implementation is much more efficient (using
> larger fragments, whereas the string stream uses variable-sized ones).
> Particularly since there are a lot of cases where string streams are
> created, converted to a string, and then logged, there's almost
> certainly a bunch of redundant work being done here.
>
> My gut feeling is that we should stick with this as-is, and maybe try
> to either work out some better integration between string streams and
> logging (to avoid that extra string allocation) or find some way of
> combining them.
>
> Regardless, this seems good as-is to me. There are some minor comments
> below, but nothing disastrous. I'll let Rae have a look over the
> various strscpy and strlcat calls, though, as while I did check them
> carefully (and KASAN hasn't complained), it's always best to have as
> many eyes on C string code as possible. :-)
>

Hello!

I have tested and taken a look at this and it looks overall good to
me. I think all of the string copying and concatenating is right.

Other than David's comments below, especially whether we should do
this with string-stream, I am pretty happy to accept this as is.

Thanks!
Rae

> But in my eyes, this is
> Reviewed-by: David Gow <davidgow@google.com>
>
> Cheers,
> -- David
>
> >  lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++---
> >  1 file changed, 61 insertions(+), 4 deletions(-)
> >
> > diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> > index dfe51bc2b387..28d0048d6171 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
> >         return frag;
> >  }
> >
> > +static void kunit_log_append_string(struct list_head *log, const char *src)
> > +{
> > +       struct kunit_log_frag *frag, *new_frag;
> > +       int log_len, bytes_left;
> > +       ssize_t written;
> > +       char *p;
> > +
> > +       frag = list_last_entry(log, struct kunit_log_frag, list);
> > +       log_len = strlen(frag->buf);
> > +       bytes_left = sizeof(frag->buf) - log_len;
> > +
> > +       written = strscpy(frag->buf + log_len, src, bytes_left);
> > +       if (written != -E2BIG)
> > +               goto newline;
> > +
> > +       src += bytes_left - 1;
> > +       do {
> > +               new_frag = kunit_log_extend(log);
> > +               if (!new_frag)
> > +                       goto newline;
> > +
> > +               frag = new_frag;
> > +               written = strscpy(frag->buf, src, sizeof(frag->buf));
> > +               src += sizeof(frag->buf) - 1;
> > +       } while (written == -E2BIG);
> > +
> > +newline:
> > +       if (written == -E2BIG)
>
> I think that this can only be true if kunit_log_extend() fails. If the
> do/while loop ends naturally, then written != -E2BIG, as is the case
> with the strscpy goto above.
>
> Do you think it's cleaner to move the 'written = strlen(frag->buf)
> into the if (!new_frag) statement within the loop?
>
> > +               written = strlen(frag->buf);
> > +
> > +       p = &frag->buf[written - 1];
> > +       if (*p != '\n') {
> > +               if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) {
> > +                       frag = kunit_log_extend(log);
> > +                       if (!frag) {
>
> A comment here could be useful. Something like "If we can't extend the
> log to add a newline, truncate the last message".
>
> > +                               *p = '\n';
> > +                               return;
> > +                       }
> > +
> > +                       frag->buf[0] = '\n';
> > +                       frag->buf[1] = '\0';
> > +               }
> > +       }
> > +}
> > +
> >  /* Append formatted message to log, extending the log buffer if necessary. */
> >  void kunit_log_append(struct list_head *log, const char *fmt, ...)
> >  {
> >         va_list args;
> >         struct kunit_log_frag *frag;
> >         int len, log_len, len_left;
> > +       char *tmp = NULL;
> >
> >         if (!log)
> >                 return;
> >
> > -       frag = list_last_entry(log, struct kunit_log_frag, list);
> > -       log_len = strlen(frag->buf);
> > -       len_left = sizeof(frag->buf) - log_len - 1;
> > -
> >         /* Evaluate length of line to add to log */
> >         va_start(args, fmt);
> >         len = vsnprintf(NULL, 0, fmt, args) + 1;
> >         va_end(args);
> >
> > +       if (len > sizeof(frag->buf) - 1) {
> > +               va_start(args, fmt);
> > +               tmp = kvasprintf(GFP_KERNEL, fmt, args);
> > +               va_end(args);
> > +
>
> Should we handle the case where kvasprintf() fails here and drop the
> log message?
>
>
> > +               kunit_log_append_string(log, tmp);
> > +               kfree(tmp);
> > +
> > +               return;
> > +       }
> > +
> > +       frag = list_last_entry(log, struct kunit_log_frag, list);
> > +       log_len = strlen(frag->buf);
> > +       len_left = sizeof(frag->buf) - log_len - 1;
> > +
> >         if (len > len_left) {
> >                 frag = kunit_log_extend(log);
> >                 if (!frag)
> > --
> > 2.30.2
> >

[PATCH v3 4/7] kunit: kunit-test: Test logging a line that exactly fills a fragment

[Richard Fitzgerald]

If a log string is the exact length of a log fragment buffer
kunit_log_append() should now exactly fill that fragment without
extending the log.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 lib/kunit/kunit-test.c | 37 +++++++++++++++++++++++++++++++++++++
 1 file changed, 37 insertions(+)

diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index c0ee33a8031e..9ac81828d018 100644
--- a/lib/kunit/kunit-test.c
+++ b/lib/kunit/kunit-test.c
@@ -763,12 +763,49 @@ static void kunit_log_extend_test_2(struct kunit *test)
 #endif
 }
 
+static void kunit_log_frag_sized_line_test(struct kunit *test)
+{
+#ifdef CONFIG_KUNIT_DEBUGFS
+	struct kunit_suite suite;
+	struct kunit_log_frag *frag, *src;
+
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, suite.log);
+
+	src = kunit_kzalloc(test, sizeof(*src), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, src);
+	memset(src->buf, 'x', sizeof(src->buf) - 2);
+	KUNIT_ASSERT_EQ(test, strlen(src->buf), sizeof(src->buf) - 2);
+
+	/* Log a string that exactly fills the fragment */
+	kunit_log_append(suite.log, "%s\n", src->buf);
+	KUNIT_EXPECT_TRUE(test, list_is_singular(suite.log));
+	KUNIT_EXPECT_EQ(test, strlen(frag->buf), sizeof(frag->buf) - 1);
+	strlcat(src->buf, "\n", sizeof(src->buf));
+	KUNIT_EXPECT_STREQ(test, frag->buf, src->buf);
+
+	/* Logging another string should extend the log */
+	kunit_log_append(suite.log, "Next\n");
+	KUNIT_EXPECT_EQ(test, list_count_nodes(suite.log), 2);
+	frag = list_last_entry(suite.log, struct kunit_log_frag, list);
+	KUNIT_EXPECT_STREQ(test, frag->buf, "Next\n");
+#else
+	kunit_skip(test, "only useful when debugfs is enabled");
+#endif
+}
+
 static struct kunit_case kunit_log_test_cases[] = {
 	KUNIT_CASE(kunit_log_init_frag_test),
 	KUNIT_CASE(kunit_log_test),
 	KUNIT_CASE(kunit_log_newline_test),
 	KUNIT_CASE(kunit_log_extend_test_1),
 	KUNIT_CASE(kunit_log_extend_test_2),
+	KUNIT_CASE(kunit_log_frag_sized_line_test),
 	{}
 };
 
-- 
2.30.2

Re: [PATCH v3 4/7] kunit: kunit-test: Test logging a line that exactly fills a fragment

[Rae Moar]

On Wed, Aug 9, 2023 at 11:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> If a log string is the exact length of a log fragment buffer
> kunit_log_append() should now exactly fill that fragment without
> extending the log.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>

Hello!

This test looks good to me. I have tested it and it seems to be working well.

I appreciate all of the assert and expect statements. I do have one
comment below.

Although, I would be happy to set this as reviewed by me after that
comment is responded to.

Thanks!
-Rae

> ---
>  lib/kunit/kunit-test.c | 37 +++++++++++++++++++++++++++++++++++++
>  1 file changed, 37 insertions(+)
>
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index c0ee33a8031e..9ac81828d018 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -763,12 +763,49 @@ static void kunit_log_extend_test_2(struct kunit *test)
>  #endif
>  }
>
> +static void kunit_log_frag_sized_line_test(struct kunit *test)
> +{
> +#ifdef CONFIG_KUNIT_DEBUGFS
> +       struct kunit_suite suite;
> +       struct kunit_log_frag *frag, *src;
> +
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);
> +       frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, suite.log);
> +
> +       src = kunit_kzalloc(test, sizeof(*src), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, src);
> +       memset(src->buf, 'x', sizeof(src->buf) - 2);
> +       KUNIT_ASSERT_EQ(test, strlen(src->buf), sizeof(src->buf) - 2);

Should this be an EXPECT instead? It doesn't seem like the test needs
to fail immediately if this fails. Let me know what you think.

> +
> +       /* Log a string that exactly fills the fragment */
> +       kunit_log_append(suite.log, "%s\n", src->buf);
> +       KUNIT_EXPECT_TRUE(test, list_is_singular(suite.log));
> +       KUNIT_EXPECT_EQ(test, strlen(frag->buf), sizeof(frag->buf) - 1);
> +       strlcat(src->buf, "\n", sizeof(src->buf));
> +       KUNIT_EXPECT_STREQ(test, frag->buf, src->buf);
> +
> +       /* Logging another string should extend the log */
> +       kunit_log_append(suite.log, "Next\n");
> +       KUNIT_EXPECT_EQ(test, list_count_nodes(suite.log), 2);
> +       frag = list_last_entry(suite.log, struct kunit_log_frag, list);
> +       KUNIT_EXPECT_STREQ(test, frag->buf, "Next\n");
> +#else
> +       kunit_skip(test, "only useful when debugfs is enabled");
> +#endif
> +}
> +
>  static struct kunit_case kunit_log_test_cases[] = {
>         KUNIT_CASE(kunit_log_init_frag_test),
>         KUNIT_CASE(kunit_log_test),
>         KUNIT_CASE(kunit_log_newline_test),
>         KUNIT_CASE(kunit_log_extend_test_1),
>         KUNIT_CASE(kunit_log_extend_test_2),
> +       KUNIT_CASE(kunit_log_frag_sized_line_test),
>         {}
>  };
>
> --
> 2.30.2
>

Re: [PATCH v3 4/7] kunit: kunit-test: Test logging a line that exactly fills a fragment

[Richard Fitzgerald]

On 9/8/23 22:22, Rae Moar wrote:
> On Wed, Aug 9, 2023 at 11:54 AM Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> If a log string is the exact length of a log fragment buffer
>> kunit_log_append() should now exactly fill that fragment without
>> extending the log.
>>
>> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> 
> Hello!
> 
> This test looks good to me. I have tested it and it seems to be working well.
> 
> I appreciate all of the assert and expect statements. I do have one
> comment below.
> 
> Although, I would be happy to set this as reviewed by me after that
> comment is responded to.
> 
> Thanks!
> -Rae
> 
>> ---
>>   lib/kunit/kunit-test.c | 37 +++++++++++++++++++++++++++++++++++++
>>   1 file changed, 37 insertions(+)
>>
>> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
>> index c0ee33a8031e..9ac81828d018 100644
>> --- a/lib/kunit/kunit-test.c
>> +++ b/lib/kunit/kunit-test.c
>> @@ -763,12 +763,49 @@ static void kunit_log_extend_test_2(struct kunit *test)
>>   #endif
>>   }
>>
>> +static void kunit_log_frag_sized_line_test(struct kunit *test)
>> +{
>> +#ifdef CONFIG_KUNIT_DEBUGFS
>> +       struct kunit_suite suite;
>> +       struct kunit_log_frag *frag, *src;
>> +
>> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
>> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
>> +       INIT_LIST_HEAD(suite.log);
>> +       frag = kunit_kzalloc(test, sizeof(*frag), GFP_KERNEL);
>> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
>> +       kunit_init_log_frag(frag);
>> +       list_add_tail(&frag->list, suite.log);
>> +
>> +       src = kunit_kzalloc(test, sizeof(*src), GFP_KERNEL);
>> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, src);
>> +       memset(src->buf, 'x', sizeof(src->buf) - 2);
>> +       KUNIT_ASSERT_EQ(test, strlen(src->buf), sizeof(src->buf) - 2);
> 
> Should this be an EXPECT instead? It doesn't seem like the test needs
> to fail immediately if this fails. Let me know what you think.

I think ASSERT is appropriate here. This isn't testing anything
(unless you don't trust memset). It's ensuring that the test data
I generate is what I expect otherwise the following testing is
invalid.

This is redundant because the first 3 lines must produce the expected
string, but I put it in to prove to myself that I can do math and
decided to leave it in.

[PATCH v3 5/7] kunit: kunit-test: Add test cases for logging very long lines

[Richard Fitzgerald]

Add kunit_log_long_line_test() to test that logging a line longer than
the buffer fragment size doesn't truncate the line.

Add extra tests to kunit_log_newline_test() for lines longer than the
buffer fragment size.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 lib/kunit/kunit-test.c | 84 +++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 83 insertions(+), 1 deletion(-)

diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index 9ac81828d018..c079550c3afd 100644
--- a/lib/kunit/kunit-test.c
+++ b/lib/kunit/kunit-test.c
@@ -609,7 +609,7 @@ static void kunit_log_newline_test(struct kunit *test)
 {
 	struct kunit_suite suite;
 	struct kunit_log_frag *frag;
-	char *p;
+	char *p, *line;
 
 	kunit_info(test, "Add newline\n");
 	if (test->log) {
@@ -635,6 +635,33 @@ static void kunit_log_newline_test(struct kunit *test)
 		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
 		KUNIT_EXPECT_NOT_NULL_MSG(test, strstr(p, "x12345678\n"),
 			"Newline not appended when fragment is full. Log is:\n'%s'", p);
+		kunit_kfree(test, p);
+
+		/* String that is much longer than a fragment */
+		line = kunit_kzalloc(test, sizeof(frag->buf) * 6, GFP_KERNEL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, line);
+		memset(line, 'x', (sizeof(frag->buf) * 6) - 1);
+		kunit_log_append(suite.log, "%s", line);
+		p = get_concatenated_log(test, suite.log, NULL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+		KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
+		KUNIT_EXPECT_NULL(test, strstr(p, "\n\n"));
+		kunit_kfree(test, p);
+
+		kunit_log_append(suite.log, "%s\n", line);
+		p = get_concatenated_log(test, suite.log, NULL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+		KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
+		KUNIT_EXPECT_NULL(test, strstr(p, "\n\n"));
+		kunit_kfree(test, p);
+
+		line[strlen(line) - 1] = '\n';
+		kunit_log_append(suite.log, "%s", line);
+		p = get_concatenated_log(test, suite.log, NULL);
+		KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+		KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
+		KUNIT_EXPECT_NULL(test, strstr(p, "\n\n"));
+		kunit_kfree(test, p);
 	} else {
 		kunit_skip(test, "only useful when debugfs is enabled");
 	}
@@ -799,6 +826,60 @@ static void kunit_log_frag_sized_line_test(struct kunit *test)
 #endif
 }
 
+static void kunit_log_long_line_test(struct kunit *test)
+{
+#ifdef CONFIG_KUNIT_DEBUGFS
+	struct kunit_suite suite;
+	struct kunit_log_frag *frag;
+	struct rnd_state rnd;
+	char *line, *p, *pn;
+	size_t line_buf_size, len;
+	int num_frags, i;
+
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
+	KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
+	list_add_tail(&frag->list, suite.log);
+
+	/* Create a very long string to be logged */
+	line_buf_size = sizeof(frag->buf) * 6;
+	line = kunit_kmalloc(test, line_buf_size, GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, line);
+	line[0] = '\0';
+
+	prandom_seed_state(&rnd, 3141592653589793238ULL);
+	len = 0;
+	do {
+		static const char fill[] =
+			"ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz";
+
+		i = prandom_u32_state(&rnd) % (sizeof(fill) - 1);
+		len = strlcat(line, &fill[i], line_buf_size);
+	} while (len < line_buf_size);
+
+	kunit_log_append(suite.log, "%s\n", line);
+
+	p = get_concatenated_log(test, suite.log, &num_frags);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
+	KUNIT_EXPECT_GT(test, num_frags, 1);
+
+	kunit_info(test, "num_frags:%d total len:%zu\n", num_frags, strlen(p));
+
+	/* Don't compare the trailing '\n' */
+	pn = strrchr(p, '\n');
+	KUNIT_EXPECT_NOT_ERR_OR_NULL(test, pn);
+	*pn = '\0';
+	KUNIT_EXPECT_EQ(test, strlen(p), strlen(line));
+	KUNIT_EXPECT_STREQ(test, p, line);
+#else
+	kunit_skip(test, "only useful when debugfs is enabled");
+#endif
+}
+
 static struct kunit_case kunit_log_test_cases[] = {
 	KUNIT_CASE(kunit_log_init_frag_test),
 	KUNIT_CASE(kunit_log_test),
@@ -806,6 +887,7 @@ static struct kunit_case kunit_log_test_cases[] = {
 	KUNIT_CASE(kunit_log_extend_test_1),
 	KUNIT_CASE(kunit_log_extend_test_2),
 	KUNIT_CASE(kunit_log_frag_sized_line_test),
+	KUNIT_CASE(kunit_log_long_line_test),
 	{}
 };
 
-- 
2.30.2

Re: [PATCH v3 5/7] kunit: kunit-test: Add test cases for logging very long lines

[Rae Moar]

On Wed, Aug 9, 2023 at 10:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Add kunit_log_long_line_test() to test that logging a line longer than
> the buffer fragment size doesn't truncate the line.
>
> Add extra tests to kunit_log_newline_test() for lines longer than the
> buffer fragment size.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>

Hello!

This test looks good to me. I have included just a few comments below.

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

Thanks!
-Rae

> ---
>  lib/kunit/kunit-test.c | 84 +++++++++++++++++++++++++++++++++++++++++-
>  1 file changed, 83 insertions(+), 1 deletion(-)
>
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index 9ac81828d018..c079550c3afd 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -609,7 +609,7 @@ static void kunit_log_newline_test(struct kunit *test)
>  {
>         struct kunit_suite suite;
>         struct kunit_log_frag *frag;
> -       char *p;
> +       char *p, *line;
>
>         kunit_info(test, "Add newline\n");
>         if (test->log) {
> @@ -635,6 +635,33 @@ static void kunit_log_newline_test(struct kunit *test)
>                 KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
>                 KUNIT_EXPECT_NOT_NULL_MSG(test, strstr(p, "x12345678\n"),
>                         "Newline not appended when fragment is full. Log is:\n'%s'", p);
> +               kunit_kfree(test, p);
> +

I really like the thoroughness of this test. However, I do wonder if
this newline test could be broken into at least 2 parts as the test is
quite long with all these additions. I spoke on this in a previous
patch and just wanted to touch on it here as well.

> +               /* String that is much longer than a fragment */
> +               line = kunit_kzalloc(test, sizeof(frag->buf) * 6, GFP_KERNEL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, line);
> +               memset(line, 'x', (sizeof(frag->buf) * 6) - 1);
> +               kunit_log_append(suite.log, "%s", line);
> +               p = get_concatenated_log(test, suite.log, NULL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +               KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
> +               KUNIT_EXPECT_NULL(test, strstr(p, "\n\n"));
> +               kunit_kfree(test, p);
> +

I would also consider adding comments between these three cases to
describe their differences and maybe what the desired behavior would
be.

> +               kunit_log_append(suite.log, "%s\n", line);
> +               p = get_concatenated_log(test, suite.log, NULL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +               KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
> +               KUNIT_EXPECT_NULL(test, strstr(p, "\n\n"));
> +               kunit_kfree(test, p);
> +
> +               line[strlen(line) - 1] = '\n';
> +               kunit_log_append(suite.log, "%s", line);
> +               p = get_concatenated_log(test, suite.log, NULL);
> +               KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +               KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
> +               KUNIT_EXPECT_NULL(test, strstr(p, "\n\n"));
> +               kunit_kfree(test, p);
>         } else {
>                 kunit_skip(test, "only useful when debugfs is enabled");
>         }
> @@ -799,6 +826,60 @@ static void kunit_log_frag_sized_line_test(struct kunit *test)
>  #endif
>  }
>
> +static void kunit_log_long_line_test(struct kunit *test)
> +{
> +#ifdef CONFIG_KUNIT_DEBUGFS
> +       struct kunit_suite suite;
> +       struct kunit_log_frag *frag;
> +       struct rnd_state rnd;
> +       char *line, *p, *pn;
> +       size_t line_buf_size, len;
> +       int num_frags, i;
> +
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);
> +       frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
> +       KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
> +       list_add_tail(&frag->list, suite.log);
> +
> +       /* Create a very long string to be logged */
> +       line_buf_size = sizeof(frag->buf) * 6;
> +       line = kunit_kmalloc(test, line_buf_size, GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, line);
> +       line[0] = '\0';
> +
> +       prandom_seed_state(&rnd, 3141592653589793238ULL);

I was a little worried about including a randomized string but since
it does not need to be reproduced here it should be fine. I also
haven't seen any issues with the tests with the randomized strings
being nondeterministic.

> +       len = 0;
> +       do {
> +               static const char fill[] =
> +                       "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz";
> +
> +               i = prandom_u32_state(&rnd) % (sizeof(fill) - 1);
> +               len = strlcat(line, &fill[i], line_buf_size);
> +       } while (len < line_buf_size);
> +
> +       kunit_log_append(suite.log, "%s\n", line);
> +
> +       p = get_concatenated_log(test, suite.log, &num_frags);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, p);
> +       KUNIT_EXPECT_GT(test, num_frags, 1);
> +
> +       kunit_info(test, "num_frags:%d total len:%zu\n", num_frags, strlen(p));
> +
> +       /* Don't compare the trailing '\n' */
> +       pn = strrchr(p, '\n');
> +       KUNIT_EXPECT_NOT_ERR_OR_NULL(test, pn);
> +       *pn = '\0';
> +       KUNIT_EXPECT_EQ(test, strlen(p), strlen(line));
> +       KUNIT_EXPECT_STREQ(test, p, line);
> +#else
> +       kunit_skip(test, "only useful when debugfs is enabled");
> +#endif
> +}
> +
>  static struct kunit_case kunit_log_test_cases[] = {
>         KUNIT_CASE(kunit_log_init_frag_test),
>         KUNIT_CASE(kunit_log_test),
> @@ -806,6 +887,7 @@ static struct kunit_case kunit_log_test_cases[] = {
>         KUNIT_CASE(kunit_log_extend_test_1),
>         KUNIT_CASE(kunit_log_extend_test_2),
>         KUNIT_CASE(kunit_log_frag_sized_line_test),
> +       KUNIT_CASE(kunit_log_long_line_test),
>         {}
>  };
>
> --
> 2.30.2
>

[PATCH v3 6/7] kunit: kunit-test: Add test of logging only a newline

[Richard Fitzgerald]

Add a test that logging a string containing only a newline appends
one newline to the log.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 lib/kunit/kunit-test.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index c079550c3afd..7e710c73c7e5 100644
--- a/lib/kunit/kunit-test.c
+++ b/lib/kunit/kunit-test.c
@@ -627,6 +627,12 @@ static void kunit_log_newline_test(struct kunit *test)
 		kunit_init_log_frag(frag);
 		list_add_tail(&frag->list, suite.log);
 
+		/* Log only a newline */
+		kunit_log_append(suite.log, "\n");
+		KUNIT_EXPECT_TRUE(test, list_is_singular(suite.log));
+		KUNIT_EXPECT_STREQ(test, frag->buf, "\n");
+		frag->buf[0] = '\0';
+
 		/* String that exactly fills fragment leaving no room for \n */
 		memset(frag->buf, 0, sizeof(frag->buf));
 		memset(frag->buf, 'x', sizeof(frag->buf) - 9);
-- 
2.30.2

Re: [PATCH v3 6/7] kunit: kunit-test: Add test of logging only a newline

[Rae Moar]

On Wed, Aug 9, 2023 at 10:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Add a test that logging a string containing only a newline appends
> one newline to the log.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>

This is a really great idea to include a test for the simple addition
of only a newline character.

This patch looks good to me. The only comment is that the newline test
is quite large and could be broken up as I said on the previous patch.

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

Thanks!
-Rae

> ---
>  lib/kunit/kunit-test.c | 6 ++++++
>  1 file changed, 6 insertions(+)
>
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index c079550c3afd..7e710c73c7e5 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -627,6 +627,12 @@ static void kunit_log_newline_test(struct kunit *test)
>                 kunit_init_log_frag(frag);
>                 list_add_tail(&frag->list, suite.log);
>
> +               /* Log only a newline */
> +               kunit_log_append(suite.log, "\n");
> +               KUNIT_EXPECT_TRUE(test, list_is_singular(suite.log));
> +               KUNIT_EXPECT_STREQ(test, frag->buf, "\n");
> +               frag->buf[0] = '\0';
> +
>                 /* String that exactly fills fragment leaving no room for \n */
>                 memset(frag->buf, 0, sizeof(frag->buf));
>                 memset(frag->buf, 'x', sizeof(frag->buf) - 9);
> --
> 2.30.2
>

[PATCH v3 7/7] kunit: Don't waste first attempt to format string in kunit_log_append()

[Richard Fitzgerald]

It's wasteful to call vsnprintf() only to figure out the length of the
string. The string might fit in the available buffer space but we have to
vsnprintf() again to do that.

Instead, attempt to format the string to the available buffer at the same
time as finding the string length. Only if the string didn't fit the
available space is it necessary to extend the log and format the string
again to a new fragment buffer.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 lib/kunit/test.c | 33 +++++++++++++++++----------------
 1 file changed, 17 insertions(+), 16 deletions(-)

diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index 28d0048d6171..230ec5e9824f 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -196,11 +196,21 @@ void kunit_log_append(struct list_head *log, const char *fmt, ...)
 	if (!log)
 		return;
 
-	/* Evaluate length of line to add to log */
+	frag = list_last_entry(log, struct kunit_log_frag, list);
+	log_len = strlen(frag->buf);
+	len_left = sizeof(frag->buf) - log_len - 1;
+
+	/* Attempt to print formatted line to current fragment */
 	va_start(args, fmt);
-	len = vsnprintf(NULL, 0, fmt, args) + 1;
+	len = vsnprintf(frag->buf + log_len, len_left, fmt, args) + 1;
 	va_end(args);
 
+	if (len <= len_left)
+		goto out_newline;
+
+	/* Abandon the truncated result of vsnprintf */
+	frag->buf[log_len] = '\0';
+
 	if (len > sizeof(frag->buf) - 1) {
 		va_start(args, fmt);
 		tmp = kvasprintf(GFP_KERNEL, fmt, args);
@@ -212,24 +222,15 @@ void kunit_log_append(struct list_head *log, const char *fmt, ...)
 		return;
 	}
 
-	frag = list_last_entry(log, struct kunit_log_frag, list);
-	log_len = strlen(frag->buf);
-	len_left = sizeof(frag->buf) - log_len - 1;
-
-	if (len > len_left) {
-		frag = kunit_log_extend(log);
-		if (!frag)
-			return;
-
-		len_left = sizeof(frag->buf) - 1;
-		log_len = 0;
-	}
+	frag = kunit_log_extend(log);
+	if (!frag)
+		return;
 
 	/* Print formatted line to the log */
 	va_start(args, fmt);
-	vsnprintf(frag->buf + log_len, min(len, len_left), fmt, args);
+	vsnprintf(frag->buf, sizeof(frag->buf) - 1, fmt, args);
 	va_end(args);
-
+out_newline:
 	/* Add newline to end of log if not already present. */
 	kunit_log_newline(frag);
 }
-- 
2.30.2

Re: [PATCH v3 7/7] kunit: Don't waste first attempt to format string in kunit_log_append()

[Rae Moar]

On Wed, Aug 9, 2023 at 10:54 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> It's wasteful to call vsnprintf() only to figure out the length of the
> string. The string might fit in the available buffer space but we have to
> vsnprintf() again to do that.
>
> Instead, attempt to format the string to the available buffer at the same
> time as finding the string length. Only if the string didn't fit the
> available space is it necessary to extend the log and format the string
> again to a new fragment buffer.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>

Hello!

I find this version slightly more confusing but I realize that the
extra vsnprintf() call is unnecessary. So I am ok with this version
except for one question below.

I am curious what David Gow thinks and it would also be good to have
another set of eyes here.

My testing of this showed no problems.

Thanks!
-Rae

> ---
>  lib/kunit/test.c | 33 +++++++++++++++++----------------
>  1 file changed, 17 insertions(+), 16 deletions(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 28d0048d6171..230ec5e9824f 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -196,11 +196,21 @@ void kunit_log_append(struct list_head *log, const char *fmt, ...)
>         if (!log)
>                 return;
>
> -       /* Evaluate length of line to add to log */
> +       frag = list_last_entry(log, struct kunit_log_frag, list);
> +       log_len = strlen(frag->buf);
> +       len_left = sizeof(frag->buf) - log_len - 1;
> +
> +       /* Attempt to print formatted line to current fragment */
>         va_start(args, fmt);
> -       len = vsnprintf(NULL, 0, fmt, args) + 1;
> +       len = vsnprintf(frag->buf + log_len, len_left, fmt, args) + 1;
>         va_end(args);
>
> +       if (len <= len_left)
> +               goto out_newline;
> +
> +       /* Abandon the truncated result of vsnprintf */
> +       frag->buf[log_len] = '\0';
> +
>         if (len > sizeof(frag->buf) - 1) {
>                 va_start(args, fmt);
>                 tmp = kvasprintf(GFP_KERNEL, fmt, args);
> @@ -212,24 +222,15 @@ void kunit_log_append(struct list_head *log, const char *fmt, ...)
>                 return;
>         }
>
> -       frag = list_last_entry(log, struct kunit_log_frag, list);
> -       log_len = strlen(frag->buf);
> -       len_left = sizeof(frag->buf) - log_len - 1;
> -
> -       if (len > len_left) {
> -               frag = kunit_log_extend(log);
> -               if (!frag)
> -                       return;
> -
> -               len_left = sizeof(frag->buf) - 1;
> -               log_len = 0;
> -       }
> +       frag = kunit_log_extend(log);

Are we meant to be using the remainder of the last fragment to its
capacity or just start again with a new fragment and leave some of the
last fragment empty? I worry we abandoned using the last fragment or
is that the intention? Let me know if I understand this correctly.

> +       if (!frag)
> +               return;
>
>         /* Print formatted line to the log */
>         va_start(args, fmt);
> -       vsnprintf(frag->buf + log_len, min(len, len_left), fmt, args);
> +       vsnprintf(frag->buf, sizeof(frag->buf) - 1, fmt, args);
>         va_end(args);
> -
> +out_newline:
>         /* Add newline to end of log if not already present. */
>         kunit_log_newline(frag);
>  }
> --
> 2.30.2
>

Re: [PATCH v3 7/7] kunit: Don't waste first attempt to format string in kunit_log_append()

[David Gow]

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

On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> It's wasteful to call vsnprintf() only to figure out the length of the
> string. The string might fit in the available buffer space but we have to
> vsnprintf() again to do that.
>
> Instead, attempt to format the string to the available buffer at the same
> time as finding the string length. Only if the string didn't fit the
> available space is it necessary to extend the log and format the string
> again to a new fragment buffer.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> ---

This looks good.

The only case I'm not totally convinced about is the last one, where
the message doesn't fit in the current log fragment, but is not a
whole fragment itself. I'm not sure if the added efficiency of not
doing a second vsprintf() is worth the memory fragmentation of always
starting a new fragment: the worst case where a log message is just
over half the length of frag->buf would result in every message being
in its own fragment (which would not necessarily have a consistent
size), and memory use would be ~doubled.

But I could accept it either way: until there's a real-world example
which strongly benefits from either implementation, let's go with
whatever we have working.

Reviewed-by: David Gow <davidgow@google.com>

Cheers,
-- David



>  lib/kunit/test.c | 33 +++++++++++++++++----------------
>  1 file changed, 17 insertions(+), 16 deletions(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 28d0048d6171..230ec5e9824f 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -196,11 +196,21 @@ void kunit_log_append(struct list_head *log, const char *fmt, ...)
>         if (!log)
>                 return;
>
> -       /* Evaluate length of line to add to log */
> +       frag = list_last_entry(log, struct kunit_log_frag, list);
> +       log_len = strlen(frag->buf);
> +       len_left = sizeof(frag->buf) - log_len - 1;
> +
> +       /* Attempt to print formatted line to current fragment */
>         va_start(args, fmt);
> -       len = vsnprintf(NULL, 0, fmt, args) + 1;
> +       len = vsnprintf(frag->buf + log_len, len_left, fmt, args) + 1;
>         va_end(args);
>
> +       if (len <= len_left)
> +               goto out_newline;
> +
> +       /* Abandon the truncated result of vsnprintf */
> +       frag->buf[log_len] = '\0';
> +
>         if (len > sizeof(frag->buf) - 1) {
>                 va_start(args, fmt);
>                 tmp = kvasprintf(GFP_KERNEL, fmt, args);
> @@ -212,24 +222,15 @@ void kunit_log_append(struct list_head *log, const char *fmt, ...)
>                 return;
>         }
>
> -       frag = list_last_entry(log, struct kunit_log_frag, list);
> -       log_len = strlen(frag->buf);
> -       len_left = sizeof(frag->buf) - log_len - 1;
> -
> -       if (len > len_left) {
> -               frag = kunit_log_extend(log);
> -               if (!frag)
> -                       return;
> -
> -               len_left = sizeof(frag->buf) - 1;
> -               log_len = 0;
> -       }
> +       frag = kunit_log_extend(log);
> +       if (!frag)
> +               return;
>
>         /* Print formatted line to the log */
>         va_start(args, fmt);
> -       vsnprintf(frag->buf + log_len, min(len, len_left), fmt, args);
> +       vsnprintf(frag->buf, sizeof(frag->buf) - 1, fmt, args);
>         va_end(args);
> -
> +out_newline:
>         /* Add newline to end of log if not already present. */
>         kunit_log_newline(frag);
>  }
> --
> 2.30.2
>

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