[PATCH 0/4] Add sysfs interface to collect reports from debugging tools

[PATCH 0/4] Add sysfs interface to collect reports from debugging tools

[Alexander Potapenko]

This patchset adds a library that captures error reports from debugging
tools like KASAN or KFENCE and exposes those reports to userspace via
sysfs. Report capturing is controlled by two new types of tracepoints:
error_report_start and error_report_end, that must be added to the tools
that want to use this new feature.

Alexander Potapenko (4):
  tracing: add error_report trace points
  lib: add error_report_notify to collect debugging tools' reports
  kfence: use error_report_start and error_report_end tracepoints
  kasan: use error_report_start and error_report_end tracepoints

 include/trace/events/error_report.h |  51 +++++
 kernel/trace/Makefile               |   1 +
 kernel/trace/error_report-traces.c  |  11 ++
 lib/Kconfig.debug                   |  14 ++
 lib/Makefile                        |   2 +
 lib/error_report_notify.c           | 278 ++++++++++++++++++++++++++++
 mm/kasan/report.c                   |  15 +-
 mm/kfence/report.c                  |   3 +
 8 files changed, 369 insertions(+), 6 deletions(-)
 create mode 100644 include/trace/events/error_report.h
 create mode 100644 kernel/trace/error_report-traces.c
 create mode 100644 lib/error_report_notify.c

-- 
2.30.0.284.gd98b1dd5eaa7-goog

[PATCH 1/4] tracing: add error_report trace points

[Alexander Potapenko]

Introduce error_report_start and error_report_end tracepoints.
Those can be used in debugging tools like KASAN, KFENCE, etc.
to provide extensions to the error reporting mechanisms (e.g. allow
tests hook into error reporting, ease error report collection from
production kernels).
Another benefit would be making use of ftrace for debugging or
benchmarking the tools themselves.

Suggested-by: Marco Elver <elver@google.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Andrey Konovalov <andreyknvl@gmail.com>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Marco Elver <elver@google.com>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: linux-mm@kvack.org
Signed-off-by: Alexander Potapenko <glider@google.com>
---
 include/trace/events/error_report.h | 51 +++++++++++++++++++++++++++++
 kernel/trace/Makefile               |  1 +
 kernel/trace/error_report-traces.c  | 11 +++++++
 3 files changed, 63 insertions(+)
 create mode 100644 include/trace/events/error_report.h
 create mode 100644 kernel/trace/error_report-traces.c

diff --git a/include/trace/events/error_report.h b/include/trace/events/error_report.h
new file mode 100644
index 000000000000..bae0129031f0
--- /dev/null
+++ b/include/trace/events/error_report.h
@@ -0,0 +1,51 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM error_report
+
+#if !defined(_TRACE_ERROR_REPORT_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_ERROR_REPORT_H
+
+#include <linux/tracepoint.h>
+
+DECLARE_EVENT_CLASS(error_report_template,
+		    TP_PROTO(const char *error_detector, unsigned long id),
+		    TP_ARGS(error_detector, id),
+		    TP_STRUCT__entry(__field(const char *, error_detector)
+					     __field(unsigned long, id)),
+		    TP_fast_assign(__entry->error_detector = error_detector;
+				   __entry->id = id;),
+		    TP_printk("[%s] %lx", __entry->error_detector,
+			      __entry->id));
+
+/**
+ * error_report_start - called before printing the error report
+ * @error_detector:	short string describing the error detection tool
+ * @id:			pseudo-unique descriptor that can help distinguish reports
+ *			from one another. Depending on the tool, good examples
+ *			could be: memory access address, call site, allocation
+ *			site, etc.
+ *
+ * This event occurs right before a debugging tool starts printing the error
+ * report.
+ */
+DEFINE_EVENT(error_report_template, error_report_start,
+	     TP_PROTO(const char *error_detector, unsigned long id),
+	     TP_ARGS(error_detector, id));
+
+/**
+ * error_report_end - called after printing the error report
+ * @error_detector:	short string describing the error detection tool
+ * @id:			pseudo-unique descriptor, matches that passed to
+ *			error_report_start
+ *
+ * This event occurs right after a debugging tool finishes printing the error
+ * report.
+ */
+DEFINE_EVENT(error_report_template, error_report_end,
+	     TP_PROTO(const char *error_detector, unsigned long id),
+	     TP_ARGS(error_detector, id));
+
+#endif /* _TRACE_ERROR_REPORT_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 7e44cea89fdc..b28d3e5013cd 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -81,6 +81,7 @@ obj-$(CONFIG_SYNTH_EVENTS) += trace_events_synth.o
 obj-$(CONFIG_HIST_TRIGGERS) += trace_events_hist.o
 obj-$(CONFIG_BPF_EVENTS) += bpf_trace.o
 obj-$(CONFIG_KPROBE_EVENTS) += trace_kprobe.o
+obj-$(CONFIG_TRACEPOINTS) += error_report-traces.o
 obj-$(CONFIG_TRACEPOINTS) += power-traces.o
 ifeq ($(CONFIG_PM),y)
 obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
diff --git a/kernel/trace/error_report-traces.c b/kernel/trace/error_report-traces.c
new file mode 100644
index 000000000000..80960c52c705
--- /dev/null
+++ b/kernel/trace/error_report-traces.c
@@ -0,0 +1,11 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Error reporting trace points
+ */
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/error_report.h>
+
+EXPORT_TRACEPOINT_SYMBOL_GPL(error_report_start);
+EXPORT_TRACEPOINT_SYMBOL_GPL(error_report_end);
+
-- 
2.30.0.284.gd98b1dd5eaa7-goog

Re: [PATCH 1/4] tracing: add error_report trace points

[Steven Rostedt]

On Wed, 13 Jan 2021 10:16:54 +0100
Alexander Potapenko <glider@google.com> wrote:

> +DECLARE_EVENT_CLASS(error_report_template,
> +		    TP_PROTO(const char *error_detector, unsigned long id),

Instead of having a random string, as this should be used by a small finite
set of subsystems, why not make the above into an enum?

> +		    TP_ARGS(error_detector, id),
> +		    TP_STRUCT__entry(__field(const char *, error_detector)
> +					     __field(unsigned long, id)),
> +		    TP_fast_assign(__entry->error_detector = error_detector;
> +				   __entry->id = id;),
> +		    TP_printk("[%s] %lx", __entry->error_detector,

Then the [%s] portion of this could also be just a __print_symbolic().

-- Steve

> +			      __entry->id));
> +
> +/**

Re: [PATCH 1/4] tracing: add error_report trace points

[Alexander Potapenko]

On Wed, Jan 13, 2021 at 10:10 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 13 Jan 2021 10:16:54 +0100
> Alexander Potapenko <glider@google.com> wrote:
>
> > +DECLARE_EVENT_CLASS(error_report_template,
> > +                 TP_PROTO(const char *error_detector, unsigned long id),
>
> Instead of having a random string, as this should be used by a small finite
> set of subsystems, why not make the above into an enum?

You're probably right.
I just thought it might be a good idea to minimize the effort needed
from tools' authors to add these tracepoints to the tools (see the
following two patches), and leave room for some extensibility (e.g.
passing bug type together with the tool name etc.)

> > +                 TP_ARGS(error_detector, id),
> > +                 TP_STRUCT__entry(__field(const char *, error_detector)
> > +                                          __field(unsigned long, id)),
> > +                 TP_fast_assign(__entry->error_detector = error_detector;
> > +                                __entry->id = id;),
> > +                 TP_printk("[%s] %lx", __entry->error_detector,
>
> Then the [%s] portion of this could also be just a __print_symbolic().

We'll need to explicitly list the enum values once again in
__print_symbolic(), right? E.g.:

enum debugging_tool {
         TOOL_KFENCE,
         TOOL_KASAN,
         ...
}

TP_printk(__print_symbolic(__entry->error_detector, TOOL_KFENCE,
TOOL_KASAN, ...),

Re: [PATCH 1/4] tracing: add error_report trace points

[Marco Elver]

On Thu, 14 Jan 2021 at 08:50, Alexander Potapenko <glider@google.com> wrote:
>
> On Wed, Jan 13, 2021 at 10:10 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Wed, 13 Jan 2021 10:16:54 +0100
> > Alexander Potapenko <glider@google.com> wrote:
> >
> > > +DECLARE_EVENT_CLASS(error_report_template,
> > > +                 TP_PROTO(const char *error_detector, unsigned long id),
> >
> > Instead of having a random string, as this should be used by a small finite
> > set of subsystems, why not make the above into an enum?
>
> You're probably right.
> I just thought it might be a good idea to minimize the effort needed
> from tools' authors to add these tracepoints to the tools (see the
> following two patches), and leave room for some extensibility (e.g.
> passing bug type together with the tool name etc.)
>
> > > +                 TP_ARGS(error_detector, id),
> > > +                 TP_STRUCT__entry(__field(const char *, error_detector)
> > > +                                          __field(unsigned long, id)),
> > > +                 TP_fast_assign(__entry->error_detector = error_detector;
> > > +                                __entry->id = id;),
> > > +                 TP_printk("[%s] %lx", __entry->error_detector,
> >
> > Then the [%s] portion of this could also be just a __print_symbolic().
>
> We'll need to explicitly list the enum values once again in
> __print_symbolic(), right? E.g.:
>
> enum debugging_tool {

We need to use TRACE_DEFINE_ENUM().

>          TOOL_KFENCE,

For consistency I would call the enum simply "ERROR_DETECTOR" as well.
(Hypothetically, there could also be an "error detector" that is not a
"debugging tool".)

>          TOOL_KASAN,
>          ...
> }
>
> TP_printk(__print_symbolic(__entry->error_detector, TOOL_KFENCE,
> TOOL_KASAN, ...),

It takes a list of val -> str. E.g.
__print_symbolic(__entry->error_detector, { TOOL_KFENCE, "KFENCE" }, {
TOOL_KASAN, "KASAN" }).

Looking around the kernel, sometimes this is simplified with macros,
but not sure if it's worth it. Typing the same thing 3 times is fine,
given this list won't grow really fast.

Thanks,
-- Marco

Re: [PATCH 1/4] tracing: add error_report trace points

[Steven Rostedt]

On Thu, 14 Jan 2021 08:49:57 +0100
Alexander Potapenko <glider@google.com> wrote:

> We'll need to explicitly list the enum values once again in
> __print_symbolic(), right? E.g.:
> 
> enum debugging_tool {
>          TOOL_KFENCE,
>          TOOL_KASAN,
>          ...
> }
> 
> TP_printk(__print_symbolic(__entry->error_detector, TOOL_KFENCE,
> TOOL_KASAN, ...),

Usually what is done is to make this into a macro:

#define REPORT_TOOL_LIST \
  EM(KFENCE, kfence) \
  EMe(KASAN, kasan)

#undef EM
#undef EMe

#define EM(a,b) TRACE_DEFINE_ENUM(a)
#define EMe(a,b) TRACE_DEFINE_ENUM(a)

REPORT_TOOL_LIST

#undef EM
#undef EMe

#define EM(a, b) { a, b },
#define EMe(a, b) { a, b }

#define show_report_tool_list(val) \
	__print_symbolic(val, REPORT_TOOL_LIST)


[..]

 TP_printk("[%s] %lx", show_report_tool_list(__entry->error_detector),
    __entry->id)


This is done in several other trace event files.  For example, see
  include/trace/events/sock.h


-- Steve

Re: [PATCH 1/4] tracing: add error_report trace points

[Alexander Potapenko]

On Thu, Jan 14, 2021 at 3:52 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Thu, 14 Jan 2021 08:49:57 +0100
> Alexander Potapenko <glider@google.com> wrote:
>
> > We'll need to explicitly list the enum values once again in
> > __print_symbolic(), right? E.g.:
> >
> > enum debugging_tool {
> >          TOOL_KFENCE,
> >          TOOL_KASAN,
> >          ...
> > }
> >
> > TP_printk(__print_symbolic(__entry->error_detector, TOOL_KFENCE,
> > TOOL_KASAN, ...),
>
> Usually what is done is to make this into a macro:
>
> #define REPORT_TOOL_LIST \
>   EM(KFENCE, kfence) \
>   EMe(KASAN, kasan)

Thanks, will be done in v2!
Note that checkpatch doesn't really like this declaration style,
claiming that "Macros with complex values should be enclosed in
parentheses".
(although it is consistent with what's done in other trace event headers)

>
> #define EM(a,b) TRACE_DEFINE_ENUM(a)
> #define EMe(a,b) TRACE_DEFINE_ENUM(a)

These lines must end with a semicolon, according to other headers (and
that becomes yet another thing that checkpatch barks at).

Re: [PATCH 1/4] tracing: add error_report trace points

[Steven Rostedt]

On Fri, 15 Jan 2021 13:53:19 +0100
Alexander Potapenko <glider@google.com> wrote:

> > #define REPORT_TOOL_LIST \
> >   EM(KFENCE, kfence) \
> >   EMe(KASAN, kasan)  
> 
> Thanks, will be done in v2!
> Note that checkpatch doesn't really like this declaration style,
> claiming that "Macros with complex values should be enclosed in
> parentheses".
> (although it is consistent with what's done in other trace event headers)

checkpatch.pl hates most of the tracing macro code ;-)

It's the one place that you can mostly ignore checkpatch reports.

-- Steve

[PATCH 2/4] lib: add error_report_notify to collect debugging tools' reports

[Alexander Potapenko]

With the introduction of various production error-detection tools, such as
MTE-based KASAN and KFENCE, the need arises to efficiently notify the
userspace OS components about kernel errors. Currently, no facility exists
to notify userspace about a kernel error from such bug-detection tools.
The problem is obviously not restricted to the above bug detection tools,
and applies to any error reporting mechanism that does not panic the
kernel; this series, however, will only add support for KASAN and KFENCE
reporting.

All such error reports appear in the kernel log. But, when such errors
occur, userspace would normally need to read the entire kernel log and
parse the relevant errors. This is error prone and inefficient, as
userspace needs to continuously monitor the kernel log for error messages.
On certain devices, this is unfortunately not acceptable. Therefore, we
need to revisit how reports are propagated to userspace.

The library added, error_report_notify (CONFIG_ERROR_REPORT_NOTIFY),
solves the above by using the error_report_start/error_report_end tracing
events and exposing the last report and the total report count to the
userspace via /sys/kernel/error_report/last_report and
/sys/kernel/error_report/report_count.

Userspace apps can call poll(POLLPRI) on those files to get notified about
the new reports without having to watch dmesg in a loop.

Suggested-by: Marco Elver <elver@google.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Andrey Konovalov <andreyknvl@gmail.com>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Marco Elver <elver@google.com>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: linux-mm@kvack.org
Signed-off-by: Alexander Potapenko <glider@google.com>
---
 lib/Kconfig.debug         |  14 ++
 lib/Makefile              |   2 +
 lib/error_report_notify.c | 278 ++++++++++++++++++++++++++++++++++++++
 3 files changed, 294 insertions(+)
 create mode 100644 lib/error_report_notify.c

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 4b8f9e018f0f..c3f4aae9f19e 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -209,6 +209,20 @@ config DEBUG_BUGVERBOSE
 	  of the BUG call as well as the EIP and oops trace.  This aids
 	  debugging but costs about 70-100K of memory.
 
+config ERROR_REPORT_NOTIFY
+	bool "Expose memory error reports to the userspace"
+	depends on TRACING
+	help
+	  When enabled, captures error reports from debugging tools (such as
+	  KFENCE or KASAN) using console tracing, and exposes reports in
+	  /sys/kernel/error_report/: the file last_report contains the last
+	  report (with maximum report length of PAGE_SIZE), and report_count,
+	  the total report count.
+
+	  Userspace programs can call poll(POLLPRI) on those files to get
+	  notified about the new reports without having to watch dmesg in a
+	  loop.
+
 endmenu # "printk and dmesg options"
 
 menu "Compile-time checks and compiler options"
diff --git a/lib/Makefile b/lib/Makefile
index afeff05fa8c5..96ed8bc0cc5b 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -240,6 +240,8 @@ obj-$(CONFIG_CPU_RMAP) += cpu_rmap.o
 
 obj-$(CONFIG_DQL) += dynamic_queue_limits.o
 
+obj-$(CONFIG_ERROR_REPORT_NOTIFY) += error_report_notify.o
+
 obj-$(CONFIG_GLOB) += glob.o
 obj-$(CONFIG_GLOB_SELFTEST) += globtest.o
 
diff --git a/lib/error_report_notify.c b/lib/error_report_notify.c
new file mode 100644
index 000000000000..b0633f36ce6d
--- /dev/null
+++ b/lib/error_report_notify.c
@@ -0,0 +1,278 @@
+// SPDX-License-Identifier: GPL-2.0
+
+/*
+ * Userspace notification interface for debugging tools.
+ *
+ * Provide two sysfs files:
+ *  - /sys/kernel/error_report/last_report
+ *  - /sys/kernel/error_report/report_count
+ * that contain the last debugging tool report (taken from dmesg, delimited by
+ * the error_report_start/error_report_end tracing events) and the total report
+ * count.
+ */
+
+#include <linux/atomic.h>
+#include <linux/fs.h>
+#include <linux/kobject.h>
+#include <linux/string.h>
+#include <linux/sysfs.h>
+#include <linux/tracepoint.h>
+#include <linux/workqueue.h>
+#include <trace/events/error_report.h>
+#include <trace/events/printk.h>
+
+static struct kobject *error_report_kobj;
+
+/* sysfs files are capped at PAGE_SIZE. */
+#define BUF_SIZE PAGE_SIZE
+/* Two buffers to store the finished report and the report being recorded. */
+static char report_buffer[2][BUF_SIZE];
+/*
+ * Total report count. Also serves as a latch for report_buffer:
+ * report_buffer[num_reports % 2] is the currently available report,
+ * report_buffer[(num_reports + 1) % 2] is the report being recorded.
+ */
+static atomic_t num_reports;
+
+/*
+ * PID of the task currently recording the report, as returned by
+ * get_encoded_pid(), or -1. Used as a writer lock for report_buffer.
+ * A regular spinlock couldn't be used here, as probe_console() can be called
+ * from any thread, and it needs to know whether that thread is holding the
+ * lock.
+ */
+static atomic_t current_pid = ATOMIC_INIT(-1);
+
+static size_t current_pos;
+static bool truncated;
+static const char TRUNC_MSG[] = "<truncated>\n";
+
+static struct delayed_work reporting_done;
+
+static void error_report_notify(struct work_struct *work)
+{
+	sysfs_notify(error_report_kobj, NULL, "last_report");
+	sysfs_notify(error_report_kobj, NULL, "report_count");
+}
+static DECLARE_DELAYED_WORK(reporting_done, error_report_notify);
+
+/*
+ * Return the current PID combined together with in_task(). This lets us
+ * distinguish between normal task context and IRQ context.
+ */
+static int get_encoded_pid(void)
+{
+	return (current->pid << 1) | (!!in_task());
+}
+
+/*
+ * Trace hook for the error_report_start event. In an unlikely case of another
+ * task already printing a report bail out, otherwise save the current pid
+ * together with in_task() return value.
+ *
+ * Because reporting code can be called from low-level routines (e.g. locking
+ * primitives or allocator guts), report recording is implemented using a
+ * seqlock lock-free algorithm.
+ */
+static void probe_report_start(void *ignore, const char *tool_name,
+			       unsigned long id)
+{
+	/*
+	 * Acquire the writer lock. Any racing probe_report_start will not
+	 * record anything. Pairs with the release in probe_report_end().
+	 */
+	if (atomic_cmpxchg_acquire(&current_pid, -1, get_encoded_pid()) != -1)
+		return;
+	current_pos = 0;
+	truncated = false;
+}
+
+/*
+ * Trace hook for the error_report_end event. If an event from the mismatching
+ * error_report_start is received, it is ignored. Otherwise, null-terminate the
+ * buffer, increase the report count (effectively releasing the report to
+ * last_report_show() and schedule a notification about a new report.
+ */
+static void probe_report_end(void *ignore, const char *tool_name,
+			     unsigned long id)
+{
+	pid_t pid = atomic_read(&current_pid);
+	int idx;
+
+	if (pid != get_encoded_pid())
+		return;
+
+	idx = (atomic_read(&num_reports) + 1) % 2;
+	if (current_pos == BUF_SIZE)
+		report_buffer[idx][current_pos - 1] = 0;
+	else
+		report_buffer[idx][current_pos] = 0;
+
+	/* Pairs with acquire in last_report_show(). */
+	atomic_inc_return_release(&num_reports);
+	schedule_delayed_work(&reporting_done, 0);
+	/*
+	 * Release the writer lock. Pairs with the acquire in
+	 * probe_report_start().
+	 */
+	atomic_set_release(&current_pid, -1);
+}
+
+/*
+ * Skip one or two leading pair of brackets containing the log timestamp and
+ * the task/CPU ID, plus the leading space, from the report line, e.g.:
+ *   [    0.698431][    T7] BUG: KFENCE: use-after-free ...
+ * becomes:
+ *   BUG: KFENCE: use-after-free ...
+ *
+ * Report size is only 4K, and this boilerplate can easily account for half of
+ * that amount.
+ */
+static void skip_extra_info(const char **buf, size_t *len)
+{
+	int num_brackets = IS_ENABLED(CONFIG_PRINTK_TIME) +
+			   IS_ENABLED(CONFIG_PRINTK_CALLER);
+	const char *found;
+
+	if (!buf || !len)
+		return;
+
+	while (num_brackets--) {
+		if (!*len || *buf[0] != '[')
+			return;
+		found = strnchr(*buf, *len, ']');
+		if (!found)
+			return;
+		*len -= found - *buf + 1;
+		*buf = found + 1;
+	}
+	if (*len && *buf[0] == ' ') {
+		++*buf;
+		--*len;
+	}
+}
+
+/*
+ * Trace hook for the console event. If a line comes from a task/CPU that did
+ * not send the error_report_start event, that line is ignored. Otherwise, it
+ * is stored in the report_buffer[(num_reports + 1) % 2].
+ *
+ * To save space, the leading timestamps and (when enabled) CPU/task info is
+ * stripped away. The buffer may contain newlines, so this procedure is
+ * repeated for every line.
+ */
+static void probe_console(void *ignore, const char *buf, size_t len)
+{
+	int pid = atomic_read(&current_pid);
+	size_t to_copy, cur_len;
+	char *newline;
+	int idx;
+
+	if (pid != get_encoded_pid() || truncated)
+		return;
+
+	idx = (atomic_read(&num_reports) + 1) % 2;
+	while (len) {
+		newline = strnchr(buf, len, '\n');
+		if (newline)
+			cur_len = newline - buf + 1;
+		else
+			cur_len = len;
+		/* Adjust len now, because skip_extra_info() may change cur_len. */
+		len -= cur_len;
+		skip_extra_info(&buf, &cur_len);
+		to_copy = min(cur_len, BUF_SIZE - current_pos);
+		memcpy(report_buffer[idx] + current_pos, buf, to_copy);
+		current_pos += to_copy;
+		if (cur_len > to_copy) {
+			truncated = true;
+			memcpy(report_buffer[idx] + current_pos - sizeof(TRUNC_MSG),
+			       TRUNC_MSG, sizeof(TRUNC_MSG));
+			break;
+		}
+		buf += cur_len;
+	}
+}
+
+static void register_tracepoints(void)
+{
+	register_trace_console(probe_console, NULL);
+	register_trace_error_report_start(probe_report_start, NULL);
+	register_trace_error_report_end(probe_report_end, NULL);
+}
+
+/*
+ * read() handler for /sys/kernel/error_report/last_report.
+ * Because the number of reports can change under our feet, check it again
+ * after copying the report, and retry if the numbers mismatch.
+ */
+static ssize_t last_report_show(struct kobject *kobj,
+				struct kobj_attribute *attr, char *buf)
+{
+	ssize_t ret;
+	int index;
+
+	do {
+		/* Pairs with release in probe_report_end(). */
+		index = atomic_read_acquire(&num_reports);
+		/*
+		 * If index and old_index mismatch, we might be accessing
+		 * report_buffer concurrently with a writer thread. In that
+		 * case the read data will be discarded.
+		 */
+		ret = data_race(strscpy(buf, report_buffer[index % 2], BUF_SIZE));
+		/*
+		 * Prevent reordering between the memcpy above and the atomic
+		 * read below.
+		 * See the comments in include/linux/seqlock.h for more
+		 * details.
+		 */
+		smp_rmb();
+	} while (index != atomic_read(&num_reports));
+	return ret;
+}
+
+/*
+ * read() handler for /sys/kernel/error_report/report_count.
+ */
+static ssize_t report_count_show(struct kobject *kobj,
+				 struct kobj_attribute *attr, char *buf)
+{
+	return scnprintf(buf, PAGE_SIZE, "%d\n", atomic_read(&num_reports));
+}
+
+static struct kobj_attribute last_report_attr = __ATTR_RO(last_report);
+static struct kobj_attribute report_count_attr = __ATTR_RO(report_count);
+static struct attribute *error_report_sysfs_attrs[] = {
+	&last_report_attr.attr,
+	&report_count_attr.attr,
+	NULL,
+};
+
+static const struct attribute_group error_report_sysfs_attr_group = {
+	.attrs = error_report_sysfs_attrs,
+};
+
+/*
+ * Set up report notification: register tracepoints and create
+ * /sys/kernel/error_report/.
+ */
+static void error_report_notify_setup(void)
+{
+	int err;
+
+	register_tracepoints();
+	error_report_kobj = kobject_create_and_add("error_report", kernel_kobj);
+	if (!error_report_kobj)
+		goto error;
+	err = sysfs_create_group(error_report_kobj,
+				 &error_report_sysfs_attr_group);
+	if (err)
+		goto error;
+	return;
+
+error:
+	if (error_report_kobj)
+		kobject_del(error_report_kobj);
+}
+late_initcall(error_report_notify_setup);
-- 
2.30.0.284.gd98b1dd5eaa7-goog

Re: [PATCH 2/4] lib: add error_report_notify to collect debugging tools' reports

[Andrew Morton]

On Wed, 13 Jan 2021 10:16:55 +0100 Alexander Potapenko <glider@google.com> wrote:

> With the introduction of various production error-detection tools, such as
> MTE-based KASAN and KFENCE, the need arises to efficiently notify the
> userspace OS components about kernel errors. Currently, no facility exists
> to notify userspace about a kernel error from such bug-detection tools.
> The problem is obviously not restricted to the above bug detection tools,
> and applies to any error reporting mechanism that does not panic the
> kernel; this series, however, will only add support for KASAN and KFENCE
> reporting.
> 
> All such error reports appear in the kernel log. But, when such errors
> occur, userspace would normally need to read the entire kernel log and
> parse the relevant errors. This is error prone and inefficient, as
> userspace needs to continuously monitor the kernel log for error messages.
> On certain devices, this is unfortunately not acceptable. Therefore, we
> need to revisit how reports are propagated to userspace.
> 
> The library added, error_report_notify (CONFIG_ERROR_REPORT_NOTIFY),
> solves the above by using the error_report_start/error_report_end tracing
> events and exposing the last report and the total report count to the
> userspace via /sys/kernel/error_report/last_report and
> /sys/kernel/error_report/report_count.
> 
> Userspace apps can call poll(POLLPRI) on those files to get notified about
> the new reports without having to watch dmesg in a loop.

It would be nice to see some user-facing documentation for this, under
Documentation/.  How to use it, what the shortcomings are, etc.

For instance...  what happens when userspace is slow reading
/sys/kernel/error_report/last_report?  Does that file buffer multiple
reports?  Does the previous one get overwritten?  etc.  Words on how
this obvious issue is handled...

> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -209,6 +209,20 @@ config DEBUG_BUGVERBOSE
>  	  of the BUG call as well as the EIP and oops trace.  This aids
>  	  debugging but costs about 70-100K of memory.
>  
> +config ERROR_REPORT_NOTIFY
> +	bool "Expose memory error reports to the userspace"

There's really nothing "memory" specific about this?  Any kernel
subsystem could use it?

> +	depends on TRACING
> +	help
> +	  When enabled, captures error reports from debugging tools (such as
> +	  KFENCE or KASAN) using console tracing, and exposes reports in
> +	  /sys/kernel/error_report/: the file last_report contains the last
> +	  report (with maximum report length of PAGE_SIZE), and report_count,
> +	  the total report count.
> +
> +	  Userspace programs can call poll(POLLPRI) on those files to get
> +	  notified about the new reports without having to watch dmesg in a
> +	  loop.

So we have a whole new way of getting debug info out of the kernel.  I
fear this will become a monster.  And anticipating that, we should make
darn sure that the interface is right, and is extensible.

Re: [PATCH 2/4] lib: add error_report_notify to collect debugging tools' reports

[Alexander Potapenko]

On Thu, Jan 14, 2021 at 1:06 AM Andrew Morton <akpm@linux-foundation.org> wrote:
>
> On Wed, 13 Jan 2021 10:16:55 +0100 Alexander Potapenko <glider@google.com> wrote:
>
> > With the introduction of various production error-detection tools, such as
> > MTE-based KASAN and KFENCE, the need arises to efficiently notify the
> > userspace OS components about kernel errors. Currently, no facility exists
> > to notify userspace about a kernel error from such bug-detection tools.
> > The problem is obviously not restricted to the above bug detection tools,
> > and applies to any error reporting mechanism that does not panic the
> > kernel; this series, however, will only add support for KASAN and KFENCE
> > reporting.
> >
> > All such error reports appear in the kernel log. But, when such errors
> > occur, userspace would normally need to read the entire kernel log and
> > parse the relevant errors. This is error prone and inefficient, as
> > userspace needs to continuously monitor the kernel log for error messages.
> > On certain devices, this is unfortunately not acceptable. Therefore, we
> > need to revisit how reports are propagated to userspace.
> >
> > The library added, error_report_notify (CONFIG_ERROR_REPORT_NOTIFY),
> > solves the above by using the error_report_start/error_report_end tracing
> > events and exposing the last report and the total report count to the
> > userspace via /sys/kernel/error_report/last_report and
> > /sys/kernel/error_report/report_count.
> >
> > Userspace apps can call poll(POLLPRI) on those files to get notified about
> > the new reports without having to watch dmesg in a loop.
>
> It would be nice to see some user-facing documentation for this, under
> Documentation/.  How to use it, what the shortcomings are, etc.

Good point, will do.

> For instance...  what happens when userspace is slow reading
> /sys/kernel/error_report/last_report?  Does that file buffer multiple
> reports?  Does the previous one get overwritten?  etc.  Words on how
> this obvious issue is handled...

Yes, there can be issues with overwriting, and the recommended way to
handle them would be to check the value in
/sys/kernel/error_report/report_count before and after reading the
report.

> > --- a/lib/Kconfig.debug
> > +++ b/lib/Kconfig.debug
> > @@ -209,6 +209,20 @@ config DEBUG_BUGVERBOSE
> >         of the BUG call as well as the EIP and oops trace.  This aids
> >         debugging but costs about 70-100K of memory.
> >
> > +config ERROR_REPORT_NOTIFY
> > +     bool "Expose memory error reports to the userspace"
>
> There's really nothing "memory" specific about this?  Any kernel
> subsystem could use it?

Indeed. Perhaps it's better to emphasize "production" here, because
users of debugging tools are more or less happy with dmesg output.

>
> > +     depends on TRACING
> > +     help
> > +       When enabled, captures error reports from debugging tools (such as
> > +       KFENCE or KASAN) using console tracing, and exposes reports in
> > +       /sys/kernel/error_report/: the file last_report contains the last
> > +       report (with maximum report length of PAGE_SIZE), and report_count,
> > +       the total report count.
> > +
> > +       Userspace programs can call poll(POLLPRI) on those files to get
> > +       notified about the new reports without having to watch dmesg in a
> > +       loop.
>
> So we have a whole new way of getting debug info out of the kernel.  I
> fear this will become a monster.  And anticipating that, we should make
> darn sure that the interface is right, and is extensible.

Let me elaborate a bit on the problem we are trying to solve here.
It is specific to Android, but other Linux-based systems may require
something similar.
There's a userspace daemon that collects kernel/userspace crashes from
the device if its owner has opted into that, and we want that daemon
to also collect non-fatal error reports.

There are several issues with that:
 - there is currently no way to synchronously notify the userspace
about an error, and without that the daemon will have to actively
monitor the kernel log (or some other file, e.g. /proc/kernel/tainted
for certain strings;
- once we figure out there is an error report available, the daemon
will have to find its beginning and end, and also filter out the lines
that do not belong to that report;
 - this all requires letting that daemon see the whole dmesg output,
which may contain sensitive data accidentally printed by the kernel.

So, first of all, our solution had to provide some poll()-based
interface to avoid reading files in a loop, and that interface should
trigger every time an error report is printed.
Adding ftrace tracepoints to every tool at the points where reports
start/end is perhaps least invasive, and also allows multiple
subscribers (plus free tracing!).
Then, since the notification library was already in the business of
trace probes, we thought it makes sense to capture the whole report,
assuming that every dmesg line from the same task/cpu between the
report probes belongs to the report.
That drastically reduces the amount of data the userspace daemon has
access to (only the report instead of the whole dmesg), and removes
the need of active polling.

A potential pinch-point is the report size, which cannot exceed 4K if
we want it to live in sysfs.
It turned out certain reports didn't fit under that limit when taken
as-is, but stripping away the timestamps and task IDs printed by
CONFIG_PRINTK_CALLER saved us 1.5-2K in those cases.

Given that the information we expose is a subset of what dmesg
provides, I wouldn't call it a "whole new way" though.
Existing users will probably still stick to dmesg unless they want to
be notified of errors.

Re: [PATCH 2/4] lib: add error_report_notify to collect debugging tools' reports

[Alexander Potapenko]

On Thu, Jan 14, 2021 at 10:51 AM Alexander Potapenko <glider@google.com> wrote:
>
> On Thu, Jan 14, 2021 at 1:06 AM Andrew Morton <akpm@linux-foundation.org> wrote:
> >
> > On Wed, 13 Jan 2021 10:16:55 +0100 Alexander Potapenko <glider@google.com> wrote:
> >
> > > With the introduction of various production error-detection tools, such as
> > > MTE-based KASAN and KFENCE, the need arises to efficiently notify the
> > > userspace OS components about kernel errors. Currently, no facility exists
> > > to notify userspace about a kernel error from such bug-detection tools.
> > > The problem is obviously not restricted to the above bug detection tools,
> > > and applies to any error reporting mechanism that does not panic the
> > > kernel; this series, however, will only add support for KASAN and KFENCE
> > > reporting.
> > >
> > > All such error reports appear in the kernel log. But, when such errors
> > > occur, userspace would normally need to read the entire kernel log and
> > > parse the relevant errors. This is error prone and inefficient, as
> > > userspace needs to continuously monitor the kernel log for error messages.
> > > On certain devices, this is unfortunately not acceptable. Therefore, we
> > > need to revisit how reports are propagated to userspace.
> > >
> > > The library added, error_report_notify (CONFIG_ERROR_REPORT_NOTIFY),
> > > solves the above by using the error_report_start/error_report_end tracing
> > > events and exposing the last report and the total report count to the
> > > userspace via /sys/kernel/error_report/last_report and
> > > /sys/kernel/error_report/report_count.
> > >
> > > Userspace apps can call poll(POLLPRI) on those files to get notified about
> > > the new reports without having to watch dmesg in a loop.
> >
> > It would be nice to see some user-facing documentation for this, under
> > Documentation/.  How to use it, what the shortcomings are, etc.
>
> Good point, will do.
Added in v2.

> > For instance...  what happens when userspace is slow reading
> > /sys/kernel/error_report/last_report?  Does that file buffer multiple
> > reports?  Does the previous one get overwritten?  etc.  Words on how
> > this obvious issue is handled...
>
> Yes, there can be issues with overwriting, and the recommended way to
> handle them would be to check the value in
> /sys/kernel/error_report/report_count before and after reading the
> report.

After looking closer it occurs to me that sysfs retains the buffer
returned by the attribute's show() method, so that one can read the
whole report up to the end even if the file contents change.

> > There's really nothing "memory" specific about this?  Any kernel
> > subsystem could use it?
>
> Indeed. Perhaps it's better to emphasize "production" here, because
> users of debugging tools are more or less happy with dmesg output.

Changed to "error reports from debugging tools".

[PATCH 3/4] kfence: use error_report_start and error_report_end tracepoints

[Alexander Potapenko]

Make it possible to trace KFENCE error reporting (in particular, for
compatibility with CONFIG_ERROR_REPORT_NOTIFY).

Suggested-by: Marco Elver <elver@google.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Andrey Konovalov <andreyknvl@gmail.com>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Marco Elver <elver@google.com>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: linux-mm@kvack.org
Signed-off-by: Alexander Potapenko <glider@google.com>
---
 mm/kfence/report.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/mm/kfence/report.c b/mm/kfence/report.c
index 4dedc2ff8f28..5c063b5b2227 100644
--- a/mm/kfence/report.c
+++ b/mm/kfence/report.c
@@ -9,6 +9,7 @@
 #include <linux/seq_file.h>
 #include <linux/stacktrace.h>
 #include <linux/string.h>
+#include <trace/events/error_report.h>
 
 #include <asm/kfence.h>
 
@@ -184,6 +185,7 @@ void kfence_report_error(unsigned long address, struct pt_regs *regs,
 	lockdep_off();
 
 	pr_err("==================================================================\n");
+	trace_error_report_start("kfence", address);
 	/* Print report header. */
 	switch (type) {
 	case KFENCE_ERROR_OOB: {
@@ -232,6 +234,7 @@ void kfence_report_error(unsigned long address, struct pt_regs *regs,
 		show_regs(regs);
 	else
 		dump_stack_print_info(KERN_ERR);
+	trace_error_report_end("kfence", address);
 	pr_err("==================================================================\n");
 
 	lockdep_on();
-- 
2.30.0.284.gd98b1dd5eaa7-goog

[PATCH 4/4] kasan: use error_report_start and error_report_end tracepoints

[Alexander Potapenko]

Make it possible to trace KASAN error reporting (in particular, for
compatibility with CONFIG_ERROR_REPORT_NOTIFY).

Suggested-by: Marco Elver <elver@google.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Andrey Konovalov <andreyknvl@gmail.com>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Marco Elver <elver@google.com>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: linux-mm@kvack.org
Signed-off-by: Alexander Potapenko <glider@google.com>
---
 mm/kasan/report.c | 15 +++++++++------
 1 file changed, 9 insertions(+), 6 deletions(-)

diff --git a/mm/kasan/report.c b/mm/kasan/report.c
index c0fb21797550..fd015dd5dd39 100644
--- a/mm/kasan/report.c
+++ b/mm/kasan/report.c
@@ -25,6 +25,7 @@
 #include <linux/module.h>
 #include <linux/sched/task_stack.h>
 #include <linux/uaccess.h>
+#include <trace/events/error_report.h>
 
 #include <asm/sections.h>
 
@@ -74,7 +75,7 @@ static void print_error_description(struct kasan_access_info *info)
 
 static DEFINE_SPINLOCK(report_lock);
 
-static void start_report(unsigned long *flags)
+static void start_report(unsigned long *flags, unsigned long addr)
 {
 	/*
 	 * Make sure we don't end up in loop.
@@ -82,10 +83,12 @@ static void start_report(unsigned long *flags)
 	kasan_disable_current();
 	spin_lock_irqsave(&report_lock, *flags);
 	pr_err("==================================================================\n");
+	trace_error_report_start("kasan", addr);
 }
 
-static void end_report(unsigned long *flags)
+static void end_report(unsigned long *flags, unsigned long addr)
 {
+	trace_error_report_end("kasan", addr);
 	pr_err("==================================================================\n");
 	add_taint(TAINT_BAD_PAGE, LOCKDEP_NOW_UNRELIABLE);
 	spin_unlock_irqrestore(&report_lock, *flags);
@@ -348,14 +351,14 @@ void kasan_report_invalid_free(void *object, unsigned long ip)
 		kasan_update_kunit_status(current->kunit_test);
 #endif /* IS_ENABLED(CONFIG_KUNIT) */
 
-	start_report(&flags);
+	start_report(&flags, (unsigned long)object);
 	pr_err("BUG: KASAN: double-free or invalid-free in %pS\n", (void *)ip);
 	print_tags(tag, object);
 	pr_err("\n");
 	print_address_description(object, tag);
 	pr_err("\n");
 	print_memory_metadata(object);
-	end_report(&flags);
+	end_report(&flags, (unsigned long)object);
 }
 
 static void __kasan_report(unsigned long addr, size_t size, bool is_write,
@@ -385,7 +388,7 @@ static void __kasan_report(unsigned long addr, size_t size, bool is_write,
 	info.is_write = is_write;
 	info.ip = ip;
 
-	start_report(&flags);
+	start_report(&flags, addr);
 
 	print_error_description(&info);
 	if (addr_has_metadata(untagged_addr))
@@ -400,7 +403,7 @@ static void __kasan_report(unsigned long addr, size_t size, bool is_write,
 		dump_stack();
 	}
 
-	end_report(&flags);
+	end_report(&flags, addr);
 }
 
 bool kasan_report(unsigned long addr, size_t size, bool is_write,
-- 
2.30.0.284.gd98b1dd5eaa7-goog