Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Wed, 19 Feb 2020 16:15:31 +0100
Message-Id: <20200219151531.161515-1-elver@google.com>
Mime-Version: 1.0
Subject: [PATCH] kcsan: Add option for verbose reporting
From:   Marco Elver <elver@google.com>
To:     elver@google.com
Cc:     paulmck@kernel.org, andreyknvl@google.com, glider@google.com,
        dvyukov@google.com, kasan-dev@googlegroups.com,
        linux-kernel@vger.kernel.org, Qian Cai <cai@lca.pw>
Content-Type: text/plain; charset="UTF-8"
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Adds CONFIG_KCSAN_VERBOSE to optionally enable more verbose reports.
Currently information about the reporting task's held locks and IRQ
trace events are shown, if they are enabled.

Signed-off-by: Marco Elver <elver@google.com>
Suggested-by: Qian Cai <cai@lca.pw>
---
 kernel/kcsan/report.c | 48 +++++++++++++++++++++++++++++++++++++++++++
 lib/Kconfig.kcsan     | 13 ++++++++++++
 2 files changed, 61 insertions(+)

diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c
index 11c791b886f3c..f14becb6f1537 100644
--- a/kernel/kcsan/report.c
+++ b/kernel/kcsan/report.c
@@ -1,10 +1,12 @@
 // SPDX-License-Identifier: GPL-2.0
 
+#include <linux/debug_locks.h>
 #include <linux/jiffies.h>
 #include <linux/kernel.h>
 #include <linux/lockdep.h>
 #include <linux/preempt.h>
 #include <linux/printk.h>
+#include <linux/rcupdate.h>
 #include <linux/sched.h>
 #include <linux/spinlock.h>
 #include <linux/stacktrace.h>
@@ -245,6 +247,29 @@ static int sym_strcmp(void *addr1, void *addr2)
 	return strncmp(buf1, buf2, sizeof(buf1));
 }
 
+static void print_verbose_info(struct task_struct *task)
+{
+	if (!task)
+		return;
+
+	if (task != current && task->state == TASK_RUNNING)
+		/*
+		 * Showing held locks for a running task is unreliable, so just
+		 * skip this. The printed locks are very likely inconsistent,
+		 * since the stack trace was obtained when the actual race
+		 * occurred and the task has since continued execution. Since we
+		 * cannot display the below information from the racing thread,
+		 * but must print it all from the watcher thread, bail out.
+		 * Note: Even if the task is not running, there is a chance that
+		 * the locks held may be inconsistent.
+		 */
+		return;
+
+	pr_err("\n");
+	debug_show_held_locks(task);
+	print_irqtrace_events(task);
+}
+
 /*
  * Returns true if a report was generated, false otherwise.
  */
@@ -319,6 +344,26 @@ static bool print_report(const volatile void *ptr, size_t size, int access_type,
 				  other_info.num_stack_entries - other_skipnr,
 				  0);
 
+		if (IS_ENABLED(CONFIG_KCSAN_VERBOSE) && other_info.task_pid != -1) {
+			struct task_struct *other_task;
+
+			/*
+			 * Rather than passing @current from the other task via
+			 * @other_info, obtain task_struct here. The problem
+			 * with passing @current via @other_info is that, we
+			 * would have to get_task_struct/put_task_struct, and if
+			 * we race with a task being released, we would have to
+			 * release it in release_report(). This may result in
+			 * deadlock if we want to use KCSAN on the allocators.
+			 * Instead, make this best-effort, and if the task was
+			 * already released, we just do not print anything here.
+			 */
+			rcu_read_lock();
+			other_task = find_task_by_pid_ns(other_info.task_pid, &init_pid_ns);
+			print_verbose_info(other_task);
+			rcu_read_unlock();
+		}
+
 		pr_err("\n");
 		pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n",
 		       get_access_type(access_type), ptr, size,
@@ -340,6 +385,9 @@ static bool print_report(const volatile void *ptr, size_t size, int access_type,
 	stack_trace_print(stack_entries + skipnr, num_stack_entries - skipnr,
 			  0);
 
+	if (IS_ENABLED(CONFIG_KCSAN_VERBOSE))
+		print_verbose_info(current);
+
 	/* Print report footer. */
 	pr_err("\n");
 	pr_err("Reported by Kernel Concurrency Sanitizer on:\n");
diff --git a/lib/Kconfig.kcsan b/lib/Kconfig.kcsan
index f0b791143c6ab..ba9268076cfbc 100644
--- a/lib/Kconfig.kcsan
+++ b/lib/Kconfig.kcsan
@@ -20,6 +20,19 @@ menuconfig KCSAN
 
 if KCSAN
 
+config KCSAN_VERBOSE
+	bool "Show verbose reports with more information about system state"
+	depends on PROVE_LOCKING
+	help
+	  If enabled, reports show more information about the system state that
+	  may help better analyze and debug races. This includes held locks and
+	  IRQ trace events.
+
+	  While this option should generally be benign, we call into more
+	  external functions on report generation; if a race report is
+	  generated from any one of them, system stability may suffer due to
+	  deadlocks or recursion.  If in doubt, say N.
+
 config KCSAN_DEBUG
 	bool "Debugging of KCSAN internals"
 
-- 
2.25.0.265.gbab2e86ba0-goog