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

[Richard Fitzgerald]

On 9/8/23 13:11, David Gow wrote:
> On Wed, 9 Aug 2023 at 17:39, Richard Fitzgerald
> <rf@xxxxxxxxxxxxxxxxxxxxx> wrote:
> > On 8/8/23 22:16, Rae Moar wrote:
> > > On Tue, Aug 8, 2023 at 8:35 AM Richard Fitzgerald
> > > <rf@xxxxxxxxxxxxxxxxxxxxx> 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@xxxxxxxxxxxxxxxxxxxxx>
> > >
> > > 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.