Received-SPF: softfail (google.com: domain of transitioning linux-kernel-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) client-ip=23.128.96.19;
Date:   Mon, 2 May 2022 09:51:46 +0200
From:   Marco Elver <elver@google.com>
To:     John Ogness <john.ogness@linutronix.de>
Cc:     Naresh Kamboju <naresh.kamboju@linaro.org>,
        Petr Mladek <pmladek@suse.com>,
        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
Message-ID: <Ym+NkkglHI5D89Dx@elver.google.com>
References: <CA+G9fYu2kS0wR4WqMRsj2rePKV9XLgOU1PiXnMvpT+Z=c2ucHA@mail.gmail.com>
 <YmwPocGA9vRSvAEN@elver.google.com>
 <87fslup9dx.fsf@jogness.linutronix.de>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <87fslup9dx.fsf@jogness.linutronix.de>
User-Agent: Mutt/2.1.4 (2021-12-11)
Precedence: bulk

On Sat, Apr 30, 2022 at 11:14PM +0206, John Ogness wrote:
[...]
> I am not familiar with how this works. Is the tracepoint getting set on
> call_console_drivers()? Or on call_console_driver()?

It's at the start of call_console_drivers(). See trace_console_rcuidle()
call.

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

I think we just need to fix the existing tracepoint, since it has
changed its semantics vs. what it was intended to be:

 | commit 95100358491abaa2e9a5483811370059bbca4645
 | Author: Johannes Berg <johannes.berg@intel.com>
 | Date:   Thu Nov 24 20:03:08 2011 +0100
 |
 |     printk/tracing: Add console output tracing
 |
 |     Add a printk.console trace point to record any printk
 |     messages into the trace, regardless of the current
 |     console loglevel. This can help correlate (existing)
 |     printk debugging with other tracing.
 |
 |     Link: http://lkml.kernel.org/r/1322161388.5366.54.camel@jlt3.sipsolutions.net
 |
 |     Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
 |     Cc: Christoph Hellwig <hch@infradead.org>
 |     Cc: Ingo Molnar <mingo@redhat.com>
 |     Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
 |     Acked-by: Thomas Gleixner <tglx@linutronix.de>
 |     Signed-off-by: Johannes Berg <johannes.berg@intel.com>
 |     Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

Specifically using it to "correlate (existing) printk debugging with
other tracing" is now broken.

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

Thanks for this! However, I think we can't have a KFENCE-specific
helper, it needs to be a tracepoint, because there are more tests that
want to check console output (kernel/kcsan/kcsan_test.c did this before
the KFENCE test actually).

My proposal would be to fix the tracepoint like so:

 | --- a/kernel/printk/printk.c
 | +++ b/kernel/printk/printk.c
 | @@ -2002,8 +2002,6 @@ static void call_console_driver(struct console *con, const char *text, size_t le
 |  {
 |  	size_t dropped_len;
 |  
 | -	trace_console_rcuidle(text, len);
 | -
 |  	if (con->dropped && dropped_text) {
 |  		dropped_len = snprintf(dropped_text, DROPPED_TEXT_MAX,
 |  				       "** %lu printk messages dropped **\n",
 | @@ -2178,6 +2176,8 @@ static u16 printk_sprint(char *text, u16 size, int facility,
 |  		}
 |  	}
 |  
 | +	trace_console_rcuidle(text, text_len);
 | +
 |  	return text_len;
 |  }

This fixes the KFENCE and KCSAN tests.

Unless I hear objections, I'll prepare a patch explaining why we need to
fix the tracepoint.

Thanks,
-- Marco