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

[Petr Mladek <pmladek@suse.com>]

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@suse.com>

Please, remove this. The patchset has changed a lot and it is not
longer true.

> --- 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.

[ 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@suse.com>
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