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

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