linux-kernel - Re: [PATCH v6 1/2] scanf: convert self-test to KUnit

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <CAJ-ks9=Tu4onRXhcSguD8ku1g6ROROhY36iozbOfN7Z1+Smghw@mail.gmail.com>
Date: Tue, 11 Feb 2025 11:08:41 -0500
From: Tamir Duberstein <tamird@...il.com>
To: Petr Mladek <pmladek@...e.com>
Cc: David Gow <davidgow@...gle.com>, Steven Rostedt <rostedt@...dmis.org>, 
	Andy Shevchenko <andriy.shevchenko@...ux.intel.com>, 
	Rasmus Villemoes <linux@...musvillemoes.dk>, Sergey Senozhatsky <senozhatsky@...omium.org>, 
	Andrew Morton <akpm@...ux-foundation.org>, Shuah Khan <shuah@...nel.org>, 
	Geert Uytterhoeven <geert@...ux-m68k.org>, linux-kernel@...r.kernel.org, 
	linux-kselftest@...r.kernel.org
Subject: Re: [PATCH v6 1/2] scanf: convert self-test to KUnit

On Tue, Feb 11, 2025 at 11:06 AM Petr Mladek <pmladek@...e.com> wrote:
>
> On Tue 2025-02-11 06:45:07, Tamir Duberstein wrote:
> > On Tue, Feb 11, 2025 at 6:37 AM Petr Mladek <pmladek@...e.com> wrote:
> > >
> > > On Mon 2025-02-10 13:13:48, Tamir Duberstein wrote:
> > > > Convert the scanf() self-test to a KUnit test.
> > > >
> > > > In the interest of keeping the patch reasonably-sized this doesn't
> > > > refactor the tests into proper parameterized tests - it's all one big
> > > > test case.
> > > >
> > > > Acked-by: Petr Mladek <pmladek@...e.com>
> > >
> > > Please, remove this. The patchset has changed a lot and it is not
> > > longer true.
> >
> > Will do.
> >
> > >
> > > > --- a/lib/test_scanf.c
> > > > +++ b/lib/scanf_kunit.c
> > > > @@ -15,67 +13,49 @@
> > > [...]
> > > >  #define _check_numbers_template(arg_fmt, expect, str, fmt, n_args, ap)               \
> > > >  do {                                                                         \
> > > > -     pr_debug("\"%s\", \"%s\" ->\n", str, fmt);                              \
> > > > +     kunit_printk(KERN_DEBUG, test, "\"%s\", \"%s\" ->", str, fmt);  \
> > >
> > > The switch from pr_debug() to kunit_printk() causes printing huge
> > > amount of messages even when the test passes.
> >
> > I'm not able to reproduce this.
>
> It is because the loglevel filtering, see below.
>
> > pr_debug expands to printk(KERN_DEBUG,
> > ...) which is also what kunit_printk(KERN_DEBUG, ...) expands to. Can
> > you help me understand how you're testing?
>
> It is more complicated, see the following in include/linux/printk.h:
>
> <paste>
> /* If you are writing a driver, please use dev_dbg instead */
> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>         (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
> #include <linux/dynamic_debug.h>
>
> /**
>  * pr_debug - Print a debug-level message conditionally
>  * @fmt: format string
>  * @...: arguments for the format string
>  *
>  * This macro expands to dynamic_pr_debug() if CONFIG_DYNAMIC_DEBUG is
>  * set. Otherwise, if DEBUG is defined, it's equivalent to a printk with
>  * KERN_DEBUG loglevel. If DEBUG is not defined it does nothing.
>  *
>  * It uses pr_fmt() to generate the format string (dynamic_pr_debug() uses
>  * pr_fmt() internally).
>  */
> #define pr_debug(fmt, ...)                      \
>         dynamic_pr_debug(fmt, ##__VA_ARGS__)
> #elif defined(DEBUG)
> #define pr_debug(fmt, ...) \
>         printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #else
> #define pr_debug(fmt, ...) \
>         no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #endif
> </paste>
>
>
> It would be nice to define it the other way around. But it would
> require reworking the macro trickery which might be tricky ;-)
>
>
> > > [ 5780.664377] KTAP version 1
> > > [ 5780.664891] 1..1
> > > [ 5780.665376]     KTAP version 1
> > > [ 5780.665765]     # Subtest: scanf
> > > [ 5780.666104]     # module: scanf_kunit
> > > [ 5780.666112]     1..10
> > > [ 5780.667354]     # numbers_simple: "0", "%llu" ->
> > > [ 5780.667371]     # numbers_simple:    0
> > > [ 5780.667923]     # numbers_simple: "0", "%llu" ->
> > > [ 5780.668321]     # numbers_simple:    0
> > > [ 5780.668803]     # numbers_simple: "1", "%llu" ->
> > > [ 5780.669175]     # numbers_simple:    1
> > > [ 5780.669624]     # numbers_simple: "18446744073709551615", "%llu" ->
> > >
> > > [... skipping 7500+ lines ...]
> > >
> > > [ 5783.157777]     # test_simple_strtol: simple_strtol("0x7fffffffffffffff", 0) -> 0x7fffffffffffffff
> > > [ 5783.158229]     # test_simple_strtol: simple_strtol("0x8000000000000001", 0) -> 0x8000000000000001
> > > [ 5783.158683]     # test_simple_strtol: simple_strtol("0x8000000000000000", 0) -> 0x8000000000000000
> > > [ 5783.159131]     # test_simple_strtol: simple_strtol("0x8000000000000000", 0) -> 0x8000000000000000
> > > [ 5783.159586]     # test_simple_strtol: simple_strtol("0x8000000000000001", 0) -> 0x8000000000000001
> > > [ 5783.160048]     # test_simple_strtol: simple_strtol("0x7fffffffffffffff", 0) -> 0x7fffffffffffffff
> > > [ 5783.160506]     # test_simple_strtol: simple_strtol("0xfffffffffffffffe", 0) -> 0xfffffffffffffffe
> > > [ 5783.160957]     # test_simple_strtol: simple_strtol("0x2", 0) -> 0x2
> > > [ 5783.161467]     # test_simple_strtol: simple_strtol("0xffffffffffffffff", 0) -> 0xffffffffffffffff
> > > [ 5783.161806]     # test_simple_strtol: simple_strtol("0x1", 0) -> 0x1
> > > [ 5783.162564]     ok 10 test_simple_strtol
> > > [ 5783.163145] # scanf: pass:10 fail:0 skip:0 total:10
> > > [ 5783.163537] # Totals: pass:22 fail:0 skip:0 total:22
> > > [ 5783.164052] ok 1 scanf
>
> I saw the above messages using "dmesg".
>
> They can also be seen in /sys/kernel/debug/kunit/scanf/results
> when CONFIG_KUNIT_DEBUGFS is enabled.
>
>
> > If you use one of the kunit userspace helpers, you will only see the
> > output when the test fails. Having said that, in my local testing I
> > don't see the KERN_DEBUG prints locally. I had to run with
> > ignore_loglevel to see them at all.
>
> Yeah, KERN_DEBUG are for the least important messages. Consoles usually
> do not print them to do not scare normal users and also historically
> because of slow serial consoles.
>
> Anyway, they are always stored into the internal log buffer. So that
> they can be seen by "dmesg" even when they were filtered on the
> console.
>
> BTW: The log buffer has a limited size. The oldest messages get lost
>      when are too many of them. Which is another reason to do not
>      print the debug messages by default.
>
>
> Best Regards,
> Petr
>
> PS: You are sending new revisions too fast. It is hard to follow.
>     I personally prefer to send one revision per week at maximum.
>     It gives people chance to find time for the review and provide
>     some feedback.

Thanks, I'll reduce the frequency. Apologies for the noise!

I think all this is addressed in v7.