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.
