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] [thread-next>] [day] [month] [year] [list]
Message-ID: <Z6t1midEnp5q1Uja@pathway.suse.cz>
Date: Tue, 11 Feb 2025 17:06:50 +0100
From: Petr Mladek <pmladek@...e.com>
To: Tamir Duberstein <tamird@...il.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 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.