On Tue, Feb 11, 2025 at 11:06 AM Petr Mladek <pmladek@xxxxxxxx> wrote:
>
> On Tue 2025-02-11 06:45:07, Tamir Duberstein wrote:
> > On Tue, Feb 11, 2025 at 6:37 AM Petr Mladek <pmladek@xxxxxxxx> 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@xxxxxxxx>
> > >
> > > 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.
