Re: [PATCH] lib: Convert test_printf.c to KUnit

[Rasmus Villemoes <linux@rasmusvillemoes.dk>]

On 21/08/2020 13.37, Petr Mladek wrote:
> On Mon 2020-08-17 09:06:32, Rasmus Villemoes wrote:
>> On 17/08/2020 06.30, Arpitha Raghunandan wrote:
>>> Converts test lib/test_printf.c to KUnit.
>>> More information about KUnit can be found at
>>> https://www.kernel.org/doc/html/latest/dev-tools/kunit/index.html.
>>> KUnit provides a common framework for unit tests in the kernel.
>>
>> So I can continue to build a kernel with some appropriate CONFIG set to
>> y, boot it under virt-me, run dmesg and see if I broke printf? That's
>> what I do now, and I don't want to have to start using some enterprisy
>> framework.
> 
> I had the same concern. I have tried it.

Thanks for doing that and reporting the results.

>     #> modprobe printf_kunit
> 
> produced the following in dmesg:
> 
> [   60.931175] printf_kunit: module verification failed: signature and/or required key missing - tainting kernel
> [   60.942209] TAP version 14
> [   60.945197]     # Subtest: printf-kunit-test
> [   60.945200]     1..1
> [   60.951092]     ok 1 - selftest
> [   60.953414] ok 1 - printf-kunit-test
> 
> I could live with the above. Then I tried to break a test by the following change:
> 
> 
> diff --git a/lib/printf_kunit.c b/lib/printf_kunit.c
> index 68ac5f9b8d28..1689dadd70a3 100644
> --- a/lib/printf_kunit.c
> +++ b/lib/printf_kunit.c
> @@ -395,7 +395,7 @@ ip4(struct kunit *kunittest)
>         sa.sin_port = cpu_to_be16(12345);
>         sa.sin_addr.s_addr = cpu_to_be32(0x7f000001);
>  
> -       test(kunittest, "127.000.000.001|127.0.0.1", "%pi4|%pI4", &sa.sin_addr, &sa.sin_addr);
> +       test(kunittest, "127-000.000.001|127.0.0.1", "%pi4|%pI4", &sa.sin_addr, &sa.sin_addr);
>         test(kunittest, "127.000.000.001|127.0.0.1", "%piS|%pIS", &sa, &sa);
>         sa.sin_addr.s_addr = cpu_to_be32(0x01020304);
>         test(kunittest, "001.002.003.004:12345|1.2.3.4:12345", "%piSp|%pISp", &sa, &sa);
> 
> 
> It produced::
> 
> [   56.786858] TAP version 14
> [   56.787493]     # Subtest: printf-kunit-test
> [   56.787494]     1..1
> [   56.788612]     # selftest: EXPECTATION FAILED at lib/printf_kunit.c:76
>                    Expected memcmp(test_buffer, expect, written) == 0, but
>                        memcmp(test_buffer, expect, written) == 1
>                        0 == 0
>                vsnprintf(buf, 256, "%pi4|%pI4", ...) wrote '127.000.000.001|127.0.0.1', expected '127-000.000.001|127.0.0.1'
> [   56.795433]     # selftest: EXPECTATION FAILED at lib/printf_kunit.c:76
>                    Expected memcmp(test_buffer, expect, written) == 0, but
>                        memcmp(test_buffer, expect, written) == 1
>                        0 == 0
>                vsnprintf(buf, 20, "%pi4|%pI4", ...) wrote '127.000.000.001|127', expected '127-000.000.001|127'
> [   56.800909]     # selftest: EXPECTATION FAILED at lib/printf_kunit.c:108
>                    Expected memcmp(p, expect, elen+1) == 0, but
>                        memcmp(p, expect, elen+1) == 1
>                        0 == 0
>                kvasprintf(..., "%pi4|%pI4", ...) returned '127.000.000.001|127.0.0.1', expected '127-000.000.001|127.0.0.1'
> [   56.806497]     not ok 1 - selftest
> [   56.806497] not ok 1 - printf-kunit-test
> 
> while the original code would have written the following error messages:
> 
> [   95.859225] test_printf: loaded.
> [   95.860031] test_printf: vsnprintf(buf, 256, "%pi4|%pI4", ...) wrote '127.000.000.001|127.0.0.1', expected '127-000.000.001|127.0.0.1'
> [   95.862630] test_printf: vsnprintf(buf, 6, "%pi4|%pI4", ...) wrote '127.0', expected '127-0'
> [   95.864118] test_printf: kvasprintf(..., "%pi4|%pI4", ...) returned '127.000.000.001|127.0.0.1', expected '127-000.000.001|127.0.0.1'
> [   95.866589] test_printf: failed 3 out of 388 tests
> 
> 
> Even the error output is acceptable for me.

Urgh. Yeah, perhaps, but the original is much more readable; it really
doesn't matter that a memcmp() fails to compare equal to 0, that's
merely how we figured out that the output was wrong.


I am just curious why
> the 2nd failure is different:
> 
>    + original code: vsnprintf(buf, 6, "%pi4|%pI4", ...) wrote '127.0', expected '127-0'
>    + kunit code: vsnprintf(buf, 20, "%pi4|%pI4", ...) wrote '127.000.000.001|127', expected '127-000.000.001|127'   

That's by design. If you read the code, there's a comment that says we
do every test case four times: With a buffer that is large enough to do
the whole output, with a 0 size buffer (that's essential to allowing
kasprintf to know how much to allocate),  with kvasprintf - but also
with a buffer size that's guaranteed to ensure the output gets truncated
somewhere. And that size is chosen randomly - I guess one could test
every single buffer size between 0 and elen+1, but that's overkill.

Now I should probably have made the tests deterministic in the sense of
getting a random seed for a PRNG, printing that seed and allowing a
module parameter to set the seed in order to repeat the exact same
tests. But so far I haven't really seen any bugs caught by test_printf
which would have been easier to fix with that.

The reason I added that "chop it off somewhere randomly" was, IIRC, due
to some %p extensions that behaved rather weirdly depending on whether
there was enough room left or not, but I fixed those bugs before
creating test_printf (and they were in turn the reason for creating
test_printf). See for example 41416f2330, where %pE at the beginning of
the format string would work ok, but if anything preceded it and the
buffer was too small we'd crash.

> 
> I am also a bit scared by the following note at
> https://www.kernel.org/doc/html/latest/dev-tools/kunit/start.html#running-tests-without-the-kunit-wrapper
> 
>    "KUnit is not designed for use in a production system, and it’s
>    possible that tests may reduce the stability or security of the
>    system."
> 
> What does it mean thay it might reduce stability or security?
> Is it because the tests might cause problems?
> Or because the kunit framework modifies functionality of the running
> system all the time?

Hm, yeah, that sounds a little frightening.

Rasmus