From 7bbe6dc0ade7e394ee1568dc9979fd0e3e155435 Mon Sep 17 00:00:00 2001 From: Mark Rutland Date: Wed, 14 Apr 2021 13:28:24 +0200 Subject: kcsan: Report observed value changes When a thread detects that a memory location was modified without its watchpoint being hit, the report notes that a change was detected, but does not provide concrete values for the change. Knowing the concrete values can be very helpful in tracking down any racy writers (e.g. as specific values may only be written in some portions of code, or under certain conditions). When we detect a modification, let's report the concrete old/new values, along with the access's mask of relevant bits (and which relevant bits were modified). This can make it easier to identify potential racy writers. As the snapshots are at most 8 bytes, we can only report values for acceses up to this size, but this appears to cater for the common case. When we detect a race via a watchpoint, we may or may not have concrete values for the modification. To be helpful, let's attempt to log them when we do as they can be ignored where irrelevant. The resulting reports appears as follows, with values zero-padded to the access width: | ================================================================== | BUG: KCSAN: data-race in el0_svc_common+0x34/0x25c arch/arm64/kernel/syscall.c:96 | | race at unknown origin, with read to 0xffff00007ae6aa00 of 8 bytes by task 223 on cpu 1: | el0_svc_common+0x34/0x25c arch/arm64/kernel/syscall.c:96 | do_el0_svc+0x48/0xec arch/arm64/kernel/syscall.c:178 | el0_svc arch/arm64/kernel/entry-common.c:226 [inline] | el0_sync_handler+0x1a4/0x390 arch/arm64/kernel/entry-common.c:236 | el0_sync+0x140/0x180 arch/arm64/kernel/entry.S:674 | | value changed: 0x0000000000000000 -> 0x0000000000000002 | | Reported by Kernel Concurrency Sanitizer on: | CPU: 1 PID: 223 Comm: syz-executor.1 Not tainted 5.8.0-rc3-00094-ga73f923ecc8e-dirty #3 | Hardware name: linux,dummy-virt (DT) | ================================================================== If an access mask is set, it is shown underneath the "value changed" line as "bits changed: 0x with mask 0x". Signed-off-by: Mark Rutland [ elver@google.com: align "value changed" and "bits changed" lines, which required massaging the message; do not print bits+mask if no mask set. ] Signed-off-by: Marco Elver Signed-off-by: Paul E. McKenney --- kernel/kcsan/report.c | 31 ++++++++++++++++++++++++++----- 1 file changed, 26 insertions(+), 5 deletions(-) (limited to 'kernel/kcsan/report.c') diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c index 50cee2357885..e37e4386f86d 100644 --- a/kernel/kcsan/report.c +++ b/kernel/kcsan/report.c @@ -327,7 +327,8 @@ static void print_verbose_info(struct task_struct *task) static void print_report(enum kcsan_value_change value_change, const struct access_info *ai, - const struct other_info *other_info) + const struct other_info *other_info, + u64 old, u64 new, u64 mask) { unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 }; int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1); @@ -407,6 +408,24 @@ static void print_report(enum kcsan_value_change value_change, if (IS_ENABLED(CONFIG_KCSAN_VERBOSE)) print_verbose_info(current); + /* Print observed value change. */ + if (ai->size <= 8) { + int hex_len = ai->size * 2; + u64 diff = old ^ new; + + if (mask) + diff &= mask; + if (diff) { + pr_err("\n"); + pr_err("value changed: 0x%0*llx -> 0x%0*llx\n", + hex_len, old, hex_len, new); + if (mask) { + pr_err(" bits changed: 0x%0*llx with mask 0x%0*llx\n", + hex_len, diff, hex_len, mask); + } + } + } + /* Print report footer. */ pr_err("\n"); pr_err("Reported by Kernel Concurrency Sanitizer on:\n"); @@ -584,7 +603,8 @@ void kcsan_report_set_info(const volatile void *ptr, size_t size, int access_typ } void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access_type, - enum kcsan_value_change value_change, int watchpoint_idx) + enum kcsan_value_change value_change, int watchpoint_idx, + u64 old, u64 new, u64 mask) { const struct access_info ai = prepare_access_info(ptr, size, access_type); struct other_info *other_info = &other_infos[watchpoint_idx]; @@ -608,7 +628,7 @@ void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access * be done once we know the full stack trace in print_report(). */ if (value_change != KCSAN_VALUE_CHANGE_FALSE) - print_report(value_change, &ai, other_info); + print_report(value_change, &ai, other_info, old, new, mask); release_report(&flags, other_info); out: @@ -616,7 +636,8 @@ out: kcsan_enable_current(); } -void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type) +void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type, + u64 old, u64 new, u64 mask) { const struct access_info ai = prepare_access_info(ptr, size, access_type); unsigned long flags; @@ -625,7 +646,7 @@ void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int acce lockdep_off(); /* See kcsan_report_known_origin(). */ raw_spin_lock_irqsave(&report_lock, flags); - print_report(KCSAN_VALUE_CHANGE_TRUE, &ai, NULL); + print_report(KCSAN_VALUE_CHANGE_TRUE, &ai, NULL, old, new, mask); raw_spin_unlock_irqrestore(&report_lock, flags); lockdep_on(); -- cgit v1.2.3