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

[John Ogness]

Hi Marco,

On 2022-04-29, Marco Elver <elver@xxxxxxxxxx> 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