| Message ID | 20230808123529.4725-3-rf@opensource.cirrus.com (mailing list archive) |
|---|---|
| State | New |
| Delegated to: | Brendan Higgins |
| Headers | show |
| Series | kunit: Add dynamically-extending log | expand |
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.
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), {} };
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(+)