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. 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?
> [ 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
>
>
> Yes, it would help with debugging. But we should print these details
> only when the test fails!
>
> Partial solution might be to use pr_debug(). The messages will be
> disabled by default and can be enabled via /sys/kernel/debug/dynamic_debug/control
>
> Here is some POC:
>
> From 7ea79fd67c4a7d8dff9d9fa986bb8dc037087c47 Mon Sep 17 00:00:00 2001
> From: Petr Mladek <pmladek@xxxxxxxx>
> Date: Tue, 11 Feb 2025 12:24:40 +0100
> Subject: [POC] kunit/scanf_knunit: Add kunit_debug() to allow using the
> dynamic debug facility
>
> Do not fill the kernel logbuffer with debug messages by default.
> Allow to enable them via /sys/kernel/debug/dynamic_debug/control
>
> The question is whether we want to print them into the kunit log.
>
> FIXME: This use just a POC. The right solution should reduce
> cut&paste.
> ---
> include/kunit/test.h | 30 ++++++++++++++++++++++++++++++
> lib/scanf_kunit.c | 6 +++---
> 2 files changed, 33 insertions(+), 3 deletions(-)
>
> diff --git a/include/kunit/test.h b/include/kunit/test.h
> index 58dbab60f853..23fa3d6b3735 100644
> --- a/include/kunit/test.h
> +++ b/include/kunit/test.h
> @@ -637,6 +637,36 @@ void __printf(2, 3) kunit_log_append(struct string_stream *log, const char *fmt,
> #define kunit_err(test, fmt, ...) \
> kunit_printk(KERN_ERR, test, fmt, ##__VA_ARGS__)
>
> +/*
> + * pr_debug and log to per-test or per-suite log buffer. Logging only done
> + * if CONFIG_KUNIT_DEBUGFS is 'y'; if it is 'n', no log is allocated/used.
> + *
> + * The special variant is needed to allow using the printk dynamic debug
> + * infrastructure, see CONFIG_DYNAMIC_DEBUG.
> + */
> +#define kunit_log_debug(test_or_suite, fmt, ...) \
> + do { \
> + pr_debug(fmt, ##__VA_ARGS__); \
> + kunit_log_append((test_or_suite)->log, fmt, \
> + ##__VA_ARGS__); \
> + } while (0)
> +
> +#define kunit_printk_debug(test, fmt, ...) \
> + kunit_log_debug(test, KUNIT_SUBTEST_INDENT "# %s: " fmt, \
> + (test)->name, ##__VA_ARGS__)
> +
> +/**
> + * kunit_debug() - Prints an DEBUG level message associated with @test.
> + *
> + * @test: The test context object.
> + * @fmt: A printk() style format string.
> + *
> + * Prints an error level message.
> + */
> +#define kunit_debug(test, fmt, ...) \
> + kunit_printk_debug(test, fmt, ##__VA_ARGS__)
> +
> +
> /*
> * Must be called at the beginning of each KUNIT_*_ASSERTION().
> * Cf. KUNIT_CURRENT_LOC.
> diff --git a/lib/scanf_kunit.c b/lib/scanf_kunit.c
> index 7e2e7d891e41..e45f3c4f0437 100644
> --- a/lib/scanf_kunit.c
> +++ b/lib/scanf_kunit.c
> @@ -42,10 +42,10 @@ _test(struct kunit *test, check_fn fn, const void *check_data, const char *strin
>
> #define _check_numbers_template(arg_fmt, expect, str, fmt, n_args, ap) \
> do { \
> - kunit_printk(KERN_DEBUG, test, "\"%s\", \"%s\" ->", str, fmt); \
> + kunit_debug(test, "\"%s\", \"%s\" ->", str, fmt); \
> for (; n_args > 0; n_args--, expect++) { \
> typeof(*expect) got = *va_arg(ap, typeof(expect)); \
> - kunit_printk(KERN_DEBUG, test, "\t" arg_fmt, got); \
> + kunit_debug(test, "\t" arg_fmt, got); \
> KUNIT_EXPECT_EQ_MSG(test, got, *expect, \
> "vsscanf(\"%s\", \"%s\", ...)", str, fmt); \
> } \
> @@ -677,7 +677,7 @@ do { \
> \
> len = snprintf(test_buffer, BUF_SIZE, gen_fmt, expect); \
> got = (fn)(test_buffer, &endp, base); \
> - kunit_printk(KERN_DEBUG, test, #fn "(\"%s\", %d) -> " gen_fmt, test_buffer, base, got); \
> + kunit_debug(test, #fn "(\"%s\", %d) -> " gen_fmt, test_buffer, base, got); \
> if (got != (expect)) { \
> KUNIT_FAIL(test, #fn "(\"%s\", %d): got " gen_fmt " expected " gen_fmt, \
> test_buffer, base, got, expect); \
> --
> 2.48.1
>
>
> But when thinking more about it. I think that even pr_debug() is not
> the right solution.
>
> IMHO, we really want to print these details only when the test fails.
>
> Best Regards,
> Petr
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.
