Add test cases for the dynamically-extending log buffer.

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_frag_sized_line_test() logs a line that exactly fills a
fragment. This should not cause an extension of the log or truncation
of the line.

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 | 204 +++++++++++++++++++++++++++++++++++++++++
 1 file changed, 204 insertions(+)

diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index 54dc011c8980..48967d12e053 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,6 +531,31 @@ 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,
+				  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)
+		len += strlen(frag->buf);
+
+	len++; /* for terminating '\0' */
+	p = kunit_kmalloc(test, len, GFP_KERNEL);
+
+	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)
 {
 	struct kunit_suite suite;
@@ -568,7 +594,9 @@ 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) {
@@ -576,14 +604,190 @@ static void kunit_log_newline_test(struct kunit *test)
 		KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
 			"Missing log line, full log:\n%s", frag->buf);
 		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_kmalloc(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_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);
+
+	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_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);
+
+	/* 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 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_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);
+
+	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);
+#else
+	kunit_skip(test, "only useful when debugfs is enabled");
+#endif
+}
+
 static struct kunit_case kunit_log_test_cases[] = {
 	KUNIT_CASE(kunit_log_test),
 	KUNIT_CASE(kunit_log_newline_test),
+	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

On Tue, Aug 8, 2023 at 8:35 AM Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Add test cases for the dynamically-extending log buffer.
>
> 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_frag_sized_line_test() logs a line that exactly fills a
> fragment. This should not cause an extension of the log or truncation
> of the line.
>
> 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!

I am happy to see so many tests in this patch series. I've been
working with these patches and the debugfs logs seem to be working
well.

However, when I ran the new kunit-log-test tests three of the tests
failed: kunit_log_extend_test_1(), kunit_log_extend_test_2(), and
kunit_log_newline_test().

The diagnostic info for kunit_log_extend_test_1() reports:

[20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
lib/kunit/kunit-test.c:705
[20:55:27] Expected p == line, but
[20:55:27]     p == "xxxxxx…xxxx12345678"
[20:55:27]     line == "The quick brown fox jumps over the lazy penguin 0"
…
[20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
lib/kunit/kunit-test.c:705
[20:55:27] Expected p == line, but
[20:55:27]     p == "The quick brown fox jumps over the lazy penguin 1"
[20:55:27]     line == "The quick brown fox jumps over the lazy penguin 4"
[20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
lib/kunit/kunit-test.c:705
[20:55:27] Expected p == line, but
[20:55:27]     p == "The quick brown fox jumps over the lazy penguin 2"
[20:55:27]     line == "The quick brown fox jumps over the lazy penguin 5"
…
[20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
lib/kunit/kunit-test.c:709
[20:55:27] Expected i == num_lines, but
[20:55:27]     i == 64 (0x40)
[20:55:27]     num_lines == 141 (0x8d)

So it looks like the log contains a different number of lines than
expected which is causing the difference of 3 between expected and
what was obtained. Potentially the log is not getting cleared/freed
properly in between test cases?

The diagnostic info for kunit_log_extend_test_2() reports:

[20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
lib/kunit/kunit-test.c:776
[20:55:27]     Expected p == &line[i], but
[20:55:27]         p ==
"xxxxx...xxxxx123456780123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
[20:55:27]         &line[i] ==
"0123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
[20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
lib/kunit/kunit-test.c:781
[20:55:27]     Expected n == num_lines, but
[20:55:27]         n == 147 (0x93)
[20:55:27]         num_lines == 155 (0x9b)
[20:55:27] Not enough lines.

Similar difference in the number of lines here.

The diagnostic info for kunit_log_newline_test() reports that the test
fails on this line:

KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');

Let me know if you are seeing similar errors. I can post the full log
if that would be helpful.

-Rae

> ---
>  lib/kunit/kunit-test.c | 204 +++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 204 insertions(+)
>
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index 54dc011c8980..48967d12e053 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,6 +531,31 @@ 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,
> +                                 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)
> +               len += strlen(frag->buf);
> +
> +       len++; /* for terminating '\0' */
> +       p = kunit_kmalloc(test, len, GFP_KERNEL);
> +
> +       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)
>  {
>         struct kunit_suite suite;
> @@ -568,7 +594,9 @@ 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) {
> @@ -576,14 +604,190 @@ static void kunit_log_newline_test(struct kunit *test)
>                 KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
>                         "Missing log line, full log:\n%s", frag->buf);
>                 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_kmalloc(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_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);
> +
> +       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_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);
> +
> +       /* 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 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_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);
> +
> +       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);
> +#else
> +       kunit_skip(test, "only useful when debugfs is enabled");
> +#endif
> +}
> +
>  static struct kunit_case kunit_log_test_cases[] = {
>         KUNIT_CASE(kunit_log_test),
>         KUNIT_CASE(kunit_log_newline_test),
> +       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
>

On 8/8/23 22:16, Rae Moar wrote:
> On Tue, Aug 8, 2023 at 8:35 AM Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> Add test cases for the dynamically-extending log buffer.
>>
>> 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_frag_sized_line_test() logs a line that exactly fills a
>> fragment. This should not cause an extension of the log or truncation
>> of the line.
>>
>> 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!
> 
> I am happy to see so many tests in this patch series. I've been
> working with these patches and the debugfs logs seem to be working
> well.
> 
> However, when I ran the new kunit-log-test tests three of the tests
> failed: kunit_log_extend_test_1(), kunit_log_extend_test_2(), and
> kunit_log_newline_test().
> 
> The diagnostic info for kunit_log_extend_test_1() reports:
> 
> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:705
> [20:55:27] Expected p == line, but
> [20:55:27]     p == "xxxxxx…xxxx12345678"
> [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 0"
> …
> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:705
> [20:55:27] Expected p == line, but
> [20:55:27]     p == "The quick brown fox jumps over the lazy penguin 1"
> [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 4"
> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:705
> [20:55:27] Expected p == line, but
> [20:55:27]     p == "The quick brown fox jumps over the lazy penguin 2"
> [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 5"
> …
> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:709
> [20:55:27] Expected i == num_lines, but
> [20:55:27]     i == 64 (0x40)
> [20:55:27]     num_lines == 141 (0x8d)
> 
> So it looks like the log contains a different number of lines than
> expected which is causing the difference of 3 between expected and
> what was obtained. Potentially the log is not getting cleared/freed
> properly in between test cases?
> 
> The diagnostic info for kunit_log_extend_test_2() reports:
> 
> [20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:776
> [20:55:27]     Expected p == &line[i], but
> [20:55:27]         p ==
> "xxxxx...xxxxx123456780123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
> [20:55:27]         &line[i] ==
> "0123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
> [20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
> lib/kunit/kunit-test.c:781
> [20:55:27]     Expected n == num_lines, but
> [20:55:27]         n == 147 (0x93)
> [20:55:27]         num_lines == 155 (0x9b)
> [20:55:27] Not enough lines.
> 
> Similar difference in the number of lines here.
> 
> The diagnostic info for kunit_log_newline_test() reports that the test
> fails on this line:
> 
> KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
> 
> Let me know if you are seeing similar errors. I can post the full log
> if that would be helpful.
> 
> -Rae
> 

Ah, I see a bug in get_concatenated_log().
Does this change fix it for you?

	len++; /* for terminating '\0' */
-	p = kunit_kmalloc(test, len, GFP_KERNEL);
+	p = kunit_kzalloc(test, len, GFP_KERNEL);

On Wed, 9 Aug 2023 at 17:39, Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> On 8/8/23 22:16, Rae Moar wrote:
> > On Tue, Aug 8, 2023 at 8:35 AM Richard Fitzgerald
> > <rf@opensource.cirrus.com> wrote:
> >>
> >> Add test cases for the dynamically-extending log buffer.
> >>
> >> 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_frag_sized_line_test() logs a line that exactly fills a
> >> fragment. This should not cause an extension of the log or truncation
> >> of the line.
> >>
> >> 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!
> >
> > I am happy to see so many tests in this patch series. I've been
> > working with these patches and the debugfs logs seem to be working
> > well.
> >
> > However, when I ran the new kunit-log-test tests three of the tests
> > failed: kunit_log_extend_test_1(), kunit_log_extend_test_2(), and
> > kunit_log_newline_test().
> >
> > The diagnostic info for kunit_log_extend_test_1() reports:
> >
> > [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> > lib/kunit/kunit-test.c:705
> > [20:55:27] Expected p == line, but
> > [20:55:27]     p == "xxxxxx…xxxx12345678"
> > [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 0"
> > …
> > [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> > lib/kunit/kunit-test.c:705
> > [20:55:27] Expected p == line, but
> > [20:55:27]     p == "The quick brown fox jumps over the lazy penguin 1"
> > [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 4"
> > [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> > lib/kunit/kunit-test.c:705
> > [20:55:27] Expected p == line, but
> > [20:55:27]     p == "The quick brown fox jumps over the lazy penguin 2"
> > [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 5"
> > …
> > [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
> > lib/kunit/kunit-test.c:709
> > [20:55:27] Expected i == num_lines, but
> > [20:55:27]     i == 64 (0x40)
> > [20:55:27]     num_lines == 141 (0x8d)
> >
> > So it looks like the log contains a different number of lines than
> > expected which is causing the difference of 3 between expected and
> > what was obtained. Potentially the log is not getting cleared/freed
> > properly in between test cases?
> >
> > The diagnostic info for kunit_log_extend_test_2() reports:
> >
> > [20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
> > lib/kunit/kunit-test.c:776
> > [20:55:27]     Expected p == &line[i], but
> > [20:55:27]         p ==
> > "xxxxx...xxxxx123456780123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
> > [20:55:27]         &line[i] ==
> > "0123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
> > [20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
> > lib/kunit/kunit-test.c:781
> > [20:55:27]     Expected n == num_lines, but
> > [20:55:27]         n == 147 (0x93)
> > [20:55:27]         num_lines == 155 (0x9b)
> > [20:55:27] Not enough lines.
> >
> > Similar difference in the number of lines here.
> >
> > The diagnostic info for kunit_log_newline_test() reports that the test
> > fails on this line:
> >
> > KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
> >
> > Let me know if you are seeing similar errors. I can post the full log
> > if that would be helpful.
> >
> > -Rae
> >
>
> Ah, I see a bug in get_concatenated_log().
> Does this change fix it for you?
>
>         len++; /* for terminating '\0' */
> -       p = kunit_kmalloc(test, len, GFP_KERNEL);
> +       p = kunit_kzalloc(test, len, GFP_KERNEL);

This fixes what seems to be the same issue for me, under x86_64/qemu.

Thanks,
-- David

On 9/8/23 13:11, David Gow wrote:
> On Wed, 9 Aug 2023 at 17:39, Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> On 8/8/23 22:16, Rae Moar wrote:
>>> On Tue, Aug 8, 2023 at 8:35 AM Richard Fitzgerald
>>> <rf@opensource.cirrus.com> wrote:
>>>>
>>>> Add test cases for the dynamically-extending log buffer.
>>>>
>>>> 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_frag_sized_line_test() logs a line that exactly fills a
>>>> fragment. This should not cause an extension of the log or truncation
>>>> of the line.
>>>>
>>>> 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!
>>>
>>> I am happy to see so many tests in this patch series. I've been
>>> working with these patches and the debugfs logs seem to be working
>>> well.
>>>
>>> However, when I ran the new kunit-log-test tests three of the tests
>>> failed: kunit_log_extend_test_1(), kunit_log_extend_test_2(), and
>>> kunit_log_newline_test().
>>>
>>> The diagnostic info for kunit_log_extend_test_1() reports:
>>>
>>> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
>>> lib/kunit/kunit-test.c:705
>>> [20:55:27] Expected p == line, but
>>> [20:55:27]     p == "xxxxxx…xxxx12345678"
>>> [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 0"
>>> …
>>> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
>>> lib/kunit/kunit-test.c:705
>>> [20:55:27] Expected p == line, but
>>> [20:55:27]     p == "The quick brown fox jumps over the lazy penguin 1"
>>> [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 4"
>>> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
>>> lib/kunit/kunit-test.c:705
>>> [20:55:27] Expected p == line, but
>>> [20:55:27]     p == "The quick brown fox jumps over the lazy penguin 2"
>>> [20:55:27]     line == "The quick brown fox jumps over the lazy penguin 5"
>>> …
>>> [20:55:27] # kunit_log_extend_test_1: EXPECTATION FAILED at
>>> lib/kunit/kunit-test.c:709
>>> [20:55:27] Expected i == num_lines, but
>>> [20:55:27]     i == 64 (0x40)
>>> [20:55:27]     num_lines == 141 (0x8d)
>>>
>>> So it looks like the log contains a different number of lines than
>>> expected which is causing the difference of 3 between expected and
>>> what was obtained. Potentially the log is not getting cleared/freed
>>> properly in between test cases?
>>>
>>> The diagnostic info for kunit_log_extend_test_2() reports:
>>>
>>> [20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
>>> lib/kunit/kunit-test.c:776
>>> [20:55:27]     Expected p == &line[i], but
>>> [20:55:27]         p ==
>>> "xxxxx...xxxxx123456780123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
>>> [20:55:27]         &line[i] ==
>>> "0123456789abcdef101112131415161718191a1b1c1d1e1f202122232425262728292a2b2c2d2e2f30313233343536373839"
>>> [20:55:27]     # kunit_log_extend_test_2: EXPECTATION FAILED at
>>> lib/kunit/kunit-test.c:781
>>> [20:55:27]     Expected n == num_lines, but
>>> [20:55:27]         n == 147 (0x93)
>>> [20:55:27]         num_lines == 155 (0x9b)
>>> [20:55:27] Not enough lines.
>>>
>>> Similar difference in the number of lines here.
>>>
>>> The diagnostic info for kunit_log_newline_test() reports that the test
>>> fails on this line:
>>>
>>> KUNIT_EXPECT_EQ(test, p[strlen(p) - 1], '\n');
>>>
>>> Let me know if you are seeing similar errors. I can post the full log
>>> if that would be helpful.
>>>
>>> -Rae
>>>
>>
>> Ah, I see a bug in get_concatenated_log().
>> Does this change fix it for you?
>>
>>          len++; /* for terminating '\0' */
>> -       p = kunit_kmalloc(test, len, GFP_KERNEL);
>> +       p = kunit_kzalloc(test, len, GFP_KERNEL);
> 
> This fixes what seems to be the same issue for me, under x86_64/qemu.
> 
> Thanks,
> -- David

Good. It seems that the various memory security options have the
side-effect of covering up this bug. I don't know which one exactly
(I've just turned them all off). I had been testing with them on.

I'll send a V3.