Re: [next] i386: kunit: ASSERTION FAILED at mm/kfence/kfence_test.c:547

From: John Ogness <john.ogness@linutronix.de>
To: Marco Elver <elver@google.com>,
	Naresh Kamboju <naresh.kamboju@linaro.org>,
	Petr Mladek <pmladek@suse.com>
Cc: Linux-Next Mailing List <linux-next@vger.kernel.org>,
	open list <linux-kernel@vger.kernel.org>,
	lkft-triage@lists.linaro.org, linux-mm <linux-mm@kvack.org>,
	Andrew Morton <akpm@linux-foundation.org>,
	Alexander Potapenko <glider@google.com>,
	Dmitry Vyukov <dvyukov@google.com>,
	Stephen Rothwell <sfr@canb.auug.org.au>,
	Anders Roxell <anders.roxell@linaro.org>,
	Andrey Konovalov <andreyknvl@gmail.com>,
	Andrey Ryabinin <ryabinin.a.a@gmail.com>,
	Catalin Marinas <catalin.marinas@arm.com>,
	Evgenii Stepanov <eugenis@google.com>,
	Mark Rutland <mark.rutland@arm.com>,
	Peter Collingbourne <pcc@google.com>,
	Vincenzo Frascino <vincenzo.frascino@arm.com>,
	Will Deacon <will@kernel.org>
Subject: Re: [next] i386: kunit: ASSERTION FAILED at mm/kfence/kfence_test.c:547
Date: Sat, 30 Apr 2022 23:14:10 +0206	[thread overview]
Message-ID: <87fslup9dx.fsf@jogness.linutronix.de> (raw)
In-Reply-To: <YmwPocGA9vRSvAEN@elver.google.com>

Hi Marco,

On 2022-04-29, Marco Elver <elver@google.com> wrote:
> And looking at your log [1], it shows that KFENCE is working just
> fine, but the logic that is supposed to intercept the kernel log (via
> tracepoint) to check that reports are being generated correctly seems
> to be broken.
>
> And this is not only i386-specific, it's also broken on a x86-64
> build.
>
> At first I thought maybe with the printk changes we'd now have to call
> pr_flush(), but that doesn't work, so I'm missing something still:
>
>  | --- a/mm/kfence/kfence_test.c
>  | +++ b/mm/kfence/kfence_test.c
>  | @@ -73,11 +73,18 @@ static void probe_console(void *ignore, const char *buf, size_t len)
>  |  }
>  |  
>  |  /* Check if a report related to the test exists. */
>  | -static bool report_available(void)
>  | +static bool __report_available(void)
>  |  {
>  |  	return READ_ONCE(observed.nlines) == ARRAY_SIZE(observed.lines);
>  |  }
>  |  
>  | +/* Check if a report related to the test exists; may sleep. */
>  | +static bool report_available(void)
>  | +{
>  | +	pr_flush(0, true);
>  | +	return __report_available();
>  | +}
>  | +

I am not familiar with how this works. Is the tracepoint getting set on
call_console_drivers()? Or on call_console_driver()?

If so, there are a couple problems with that. First off, the prototype
for that function has changed. Second, that function is called when text
is printed, but this is not when the text was created. With the
kthreads, the printing can be significantly delayed.

Since printk() is now lockless and console printing is delayed, it
becomes a bit tricky to parse the records in the existing code using a
tracepoint.

I wonder if creating a NOP function for the kfence probe to attach to
would be more appropriate. In printk_sprint() we get the text after
space has been reserved, but before the text is committed to the
ringbuffer. This is guaranteed to be called from within the printk()
context.

Here is an example of what I am thinking...

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2227,6 +2227,10 @@ static u16 printk_sprint(char *text, u16 size, int facility,
 		}
 	}
 
+#ifdef CONFIG_KFENCE_KUNIT_TEST
+	printk_kfence_check(text, text_len);
+#endif
+
 	return text_len;
 }
 
The probe_console() could attach to a NOP function printk_kfence_check().

John
