summaryrefslogtreecommitdiffstats
path: root/kernel/kcsan/report.c
blob: ac5f8345bae90b19e8761bf6e04499b954837400 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
// SPDX-License-Identifier: GPL-2.0

#include <linux/debug_locks.h>
#include <linux/delay.h>
#include <linux/jiffies.h>
#include <linux/kernel.h>
#include <linux/lockdep.h>
#include <linux/preempt.h>
#include <linux/printk.h>
#include <linux/sched.h>
#include <linux/spinlock.h>
#include <linux/stacktrace.h>

#include "kcsan.h"
#include "encoding.h"

/*
 * Max. number of stack entries to show in the report.
 */
#define NUM_STACK_ENTRIES 64

/* Common access info. */
struct access_info {
	const volatile void	*ptr;
	size_t			size;
	int			access_type;
	int			task_pid;
	int			cpu_id;
};

/*
 * Other thread info: communicated from other racing thread to thread that set
 * up the watchpoint, which then prints the complete report atomically.
 */
struct other_info {
	struct access_info	ai;
	unsigned long		stack_entries[NUM_STACK_ENTRIES];
	int			num_stack_entries;

	/*
	 * Optionally pass @current. Typically we do not need to pass @current
	 * via @other_info since just @task_pid is sufficient. Passing @current
	 * has additional overhead.
	 *
	 * To safely pass @current, we must either use get_task_struct/
	 * put_task_struct, or stall the thread that populated @other_info.
	 *
	 * We cannot rely on get_task_struct/put_task_struct in case
	 * release_report() races with a task being released, and would have to
	 * free it in release_report(). This may result in deadlock if we want
	 * to use KCSAN on the allocators.
	 *
	 * Since we also want to reliably print held locks for
	 * CONFIG_KCSAN_VERBOSE, the current implementation stalls the thread
	 * that populated @other_info until it has been consumed.
	 */
	struct task_struct	*task;
};

/*
 * To never block any producers of struct other_info, we need as many elements
 * as we have watchpoints (upper bound on concurrent races to report).
 */
static struct other_info other_infos[CONFIG_KCSAN_NUM_WATCHPOINTS + NUM_SLOTS-1];

/*
 * Information about reported races; used to rate limit reporting.
 */
struct report_time {
	/*
	 * The last time the race was reported.
	 */
	unsigned long time;

	/*
	 * The frames of the 2 threads; if only 1 thread is known, one frame
	 * will be 0.
	 */
	unsigned long frame1;
	unsigned long frame2;
};

/*
 * Since we also want to be able to debug allocators with KCSAN, to avoid
 * deadlock, report_times cannot be dynamically resized with krealloc in
 * rate_limit_report.
 *
 * Therefore, we use a fixed-size array, which at most will occupy a page. This
 * still adequately rate limits reports, assuming that a) number of unique data
 * races is not excessive, and b) occurrence of unique races within the
 * same time window is limited.
 */
#define REPORT_TIMES_MAX (PAGE_SIZE / sizeof(struct report_time))
#define REPORT_TIMES_SIZE                                                      \
	(CONFIG_KCSAN_REPORT_ONCE_IN_MS > REPORT_TIMES_MAX ?                   \
		 REPORT_TIMES_MAX :                                            \
		 CONFIG_KCSAN_REPORT_ONCE_IN_MS)
static struct report_time report_times[REPORT_TIMES_SIZE];

/*
 * Spinlock serializing report generation, and access to @other_infos. Although
 * it could make sense to have a finer-grained locking story for @other_infos,
 * report generation needs to be serialized either way, so not much is gained.
 */
static DEFINE_RAW_SPINLOCK(report_lock);

/*
 * Checks if the race identified by thread frames frame1 and frame2 has
 * been reported since (now - KCSAN_REPORT_ONCE_IN_MS).
 */
static bool rate_limit_report(unsigned long frame1, unsigned long frame2)
{
	struct report_time *use_entry = &report_times[0];
	unsigned long invalid_before;
	int i;

	BUILD_BUG_ON(CONFIG_KCSAN_REPORT_ONCE_IN_MS != 0 && REPORT_TIMES_SIZE == 0);

	if (CONFIG_KCSAN_REPORT_ONCE_IN_MS == 0)
		return false;

	invalid_before = jiffies - msecs_to_jiffies(CONFIG_KCSAN_REPORT_ONCE_IN_MS);

	/* Check if a matching race report exists. */
	for (i = 0; i < REPORT_TIMES_SIZE; ++i) {
		struct report_time *rt = &report_times[i];

		/*
		 * Must always select an entry for use to store info as we
		 * cannot resize report_times; at the end of the scan, use_entry
		 * will be the oldest entry, which ideally also happened before
		 * KCSAN_REPORT_ONCE_IN_MS ago.
		 */
		if (time_before(rt->time, use_entry->time))
			use_entry = rt;

		/*
		 * Initially, no need to check any further as this entry as well
		 * as following entries have never been used.
		 */
		if (rt->time == 0)
			break;

		/* Check if entry expired. */
		if (time_before(rt->time, invalid_before))
			continue; /* before KCSAN_REPORT_ONCE_IN_MS ago */

		/* Reported recently, check if race matches. */
		if ((rt->frame1 == frame1 && rt->frame2 == frame2) ||
		    (rt->frame1 == frame2 && rt->frame2 == frame1))
			return true;
	}

	use_entry->time = jiffies;
	use_entry->frame1 = frame1;
	use_entry->frame2 = frame2;
	return false;
}

/*
 * Special rules to skip reporting.
 */
static bool
skip_report(enum kcsan_value_change value_change, unsigned long top_frame)
{
	/* Should never get here if value_change==FALSE. */
	WARN_ON_ONCE(value_change == KCSAN_VALUE_CHANGE_FALSE);

	/*
	 * The first call to skip_report always has value_change==TRUE, since we
	 * cannot know the value written of an instrumented access. For the 2nd
	 * call there are 6 cases with CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY:
	 *
	 * 1. read watchpoint, conflicting write (value_change==TRUE): report;
	 * 2. read watchpoint, conflicting write (value_change==MAYBE): skip;
	 * 3. write watchpoint, conflicting write (value_change==TRUE): report;
	 * 4. write watchpoint, conflicting write (value_change==MAYBE): skip;
	 * 5. write watchpoint, conflicting read (value_change==MAYBE): skip;
	 * 6. write watchpoint, conflicting read (value_change==TRUE): report;
	 *
	 * Cases 1-4 are intuitive and expected; case 5 ensures we do not report
	 * data races where the write may have rewritten the same value; case 6
	 * is possible either if the size is larger than what we check value
	 * changes for or the access type is KCSAN_ACCESS_ASSERT.
	 */
	if (IS_ENABLED(CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY) &&
	    value_change == KCSAN_VALUE_CHANGE_MAYBE) {
		/*
		 * The access is a write, but the data value did not change.
		 *
		 * We opt-out of this filter for certain functions at request of
		 * maintainers.
		 */
		char buf[64];
		int len = scnprintf(buf, sizeof(buf), "%ps", (void *)top_frame);

		if (!strnstr(buf, "rcu_", len) &&
		    !strnstr(buf, "_rcu", len) &&
		    !strnstr(buf, "_srcu", len))
			return true;
	}

	return kcsan_skip_report_debugfs(top_frame);
}

static const char *get_access_type(int type)
{
	if (type & KCSAN_ACCESS_ASSERT) {
		if (type & KCSAN_ACCESS_SCOPED) {
			if (type & KCSAN_ACCESS_WRITE)
				return "assert no accesses (scoped)";
			else
				return "assert no writes (scoped)";
		} else {
			if (type & KCSAN_ACCESS_WRITE)
				return "assert no accesses";
			else
				return "assert no writes";
		}
	}

	switch (type) {
	case 0:
		return "read";
	case KCSAN_ACCESS_ATOMIC:
		return "read (marked)";
	case KCSAN_ACCESS_WRITE:
		return "write";
	case KCSAN_ACCESS_WRITE | KCSAN_ACCESS_ATOMIC:
		return "write (marked)";
	case KCSAN_ACCESS_SCOPED:
		return "read (scoped)";
	case KCSAN_ACCESS_SCOPED | KCSAN_ACCESS_ATOMIC:
		return "read (marked, scoped)";
	case KCSAN_ACCESS_SCOPED | KCSAN_ACCESS_WRITE:
		return "write (scoped)";
	case KCSAN_ACCESS_SCOPED | KCSAN_ACCESS_WRITE | KCSAN_ACCESS_ATOMIC:
		return "write (marked, scoped)";
	default:
		BUG();
	}
}

static const char *get_bug_type(int type)
{
	return (type & KCSAN_ACCESS_ASSERT) != 0 ? "assert: race" : "data-race";
}

/* Return thread description: in task or interrupt. */
static const char *get_thread_desc(int task_id)
{
	if (task_id != -1) {
		static char buf[32]; /* safe: protected by report_lock */

		snprintf(buf, sizeof(buf), "task %i", task_id);
		return buf;
	}
	return "interrupt";
}

/* Helper to skip KCSAN-related functions in stack-trace. */
static int get_stack_skipnr(const unsigned long stack_entries[], int num_entries)
{
	char buf[64];
	char *cur;
	int len, skip;

	for (skip = 0; skip < num_entries; ++skip) {
		len = scnprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skip]);

		/* Never show tsan_* or {read,write}_once_size. */
		if (strnstr(buf, "tsan_", len) ||
		    strnstr(buf, "_once_size", len))
			continue;

		cur = strnstr(buf, "kcsan_", len);
		if (cur) {
			cur += sizeof("kcsan_") - 1;
			if (strncmp(cur, "test", sizeof("test") - 1))
				continue; /* KCSAN runtime function. */
			/* KCSAN related test. */
		}

		/*
		 * No match for runtime functions -- @skip entries to skip to
		 * get to first frame of interest.
		 */
		break;
	}

	return skip;
}

/* Compares symbolized strings of addr1 and addr2. */
static int sym_strcmp(void *addr1, void *addr2)
{
	char buf1[64];
	char buf2[64];

	snprintf(buf1, sizeof(buf1), "%pS", addr1);
	snprintf(buf2, sizeof(buf2), "%pS", addr2);

	return strncmp(buf1, buf2, sizeof(buf1));
}

static void print_verbose_info(struct task_struct *task)
{
	if (!task)
		return;

	pr_err("\n");
	debug_show_held_locks(task);
	print_irqtrace_events(task);
}

/*
 * Returns true if a report was generated, false otherwise.
 */
static bool print_report(enum kcsan_value_change value_change,
			 enum kcsan_report_type type,
			 const struct access_info *ai,
			 const struct other_info *other_info)
{
	unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 };
	int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1);
	int skipnr = get_stack_skipnr(stack_entries, num_stack_entries);
	unsigned long this_frame = stack_entries[skipnr];
	unsigned long other_frame = 0;
	int other_skipnr = 0; /* silence uninit warnings */

	/*
	 * Must check report filter rules before starting to print.
	 */
	if (skip_report(KCSAN_VALUE_CHANGE_TRUE, stack_entries[skipnr]))
		return false;

	if (type == KCSAN_REPORT_RACE_SIGNAL) {
		other_skipnr = get_stack_skipnr(other_info->stack_entries,
						other_info->num_stack_entries);
		other_frame = other_info->stack_entries[other_skipnr];

		/* @value_change is only known for the other thread */
		if (skip_report(value_change, other_frame))
			return false;
	}

	if (rate_limit_report(this_frame, other_frame))
		return false;

	/* Print report header. */
	pr_err("==================================================================\n");
	switch (type) {
	case KCSAN_REPORT_RACE_SIGNAL: {
		int cmp;

		/*
		 * Order functions lexographically for consistent bug titles.
		 * Do not print offset of functions to keep title short.
		 */
		cmp = sym_strcmp((void *)other_frame, (void *)this_frame);
		pr_err("BUG: KCSAN: %s in %ps / %ps\n",
		       get_bug_type(ai->access_type | other_info->ai.access_type),
		       (void *)(cmp < 0 ? other_frame : this_frame),
		       (void *)(cmp < 0 ? this_frame : other_frame));
	} break;

	case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN:
		pr_err("BUG: KCSAN: %s in %pS\n", get_bug_type(ai->access_type),
		       (void *)this_frame);
		break;

	default:
		BUG();
	}

	pr_err("\n");

	/* Print information about the racing accesses. */
	switch (type) {
	case KCSAN_REPORT_RACE_SIGNAL:
		pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n",
		       get_access_type(other_info->ai.access_type), other_info->ai.ptr,
		       other_info->ai.size, get_thread_desc(other_info->ai.task_pid),
		       other_info->ai.cpu_id);

		/* Print the other thread's stack trace. */
		stack_trace_print(other_info->stack_entries + other_skipnr,
				  other_info->num_stack_entries - other_skipnr,
				  0);

		if (IS_ENABLED(CONFIG_KCSAN_VERBOSE))
			print_verbose_info(other_info->task);

		pr_err("\n");
		pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n",
		       get_access_type(ai->access_type), ai->ptr, ai->size,
		       get_thread_desc(ai->task_pid), ai->cpu_id);
		break;

	case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN:
		pr_err("race at unknown origin, with %s to 0x%px of %zu bytes by %s on cpu %i:\n",
		       get_access_type(ai->access_type), ai->ptr, ai->size,
		       get_thread_desc(ai->task_pid), ai->cpu_id);
		break;

	default:
		BUG();
	}
	/* Print stack trace of this thread. */
	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");
	dump_stack_print_info(KERN_DEFAULT);
	pr_err("==================================================================\n");

	return true;
}

static void release_report(unsigned long *flags, struct other_info *other_info)
{
	if (other_info)
		/*
		 * Use size to denote valid/invalid, since KCSAN entirely
		 * ignores 0-sized accesses.
		 */
		other_info->ai.size = 0;

	raw_spin_unlock_irqrestore(&report_lock, *flags);
}

/*
 * Sets @other_info->task and awaits consumption of @other_info.
 *
 * Precondition: report_lock is held.
 * Postcondition: report_lock is held.
 */
static void set_other_info_task_blocking(unsigned long *flags,
					 const struct access_info *ai,
					 struct other_info *other_info)
{
	/*
	 * We may be instrumenting a code-path where current->state is already
	 * something other than TASK_RUNNING.
	 */
	const bool is_running = current->state == TASK_RUNNING;
	/*
	 * To avoid deadlock in case we are in an interrupt here and this is a
	 * race with a task on the same CPU (KCSAN_INTERRUPT_WATCHER), provide a
	 * timeout to ensure this works in all contexts.
	 *
	 * Await approximately the worst case delay of the reporting thread (if
	 * we are not interrupted).
	 */
	int timeout = max(kcsan_udelay_task, kcsan_udelay_interrupt);

	other_info->task = current;
	do {
		if (is_running) {
			/*
			 * Let lockdep know the real task is sleeping, to print
			 * the held locks (recall we turned lockdep off, so
			 * locking/unlocking @report_lock won't be recorded).
			 */
			set_current_state(TASK_UNINTERRUPTIBLE);
		}
		raw_spin_unlock_irqrestore(&report_lock, *flags);
		/*
		 * We cannot call schedule() since we also cannot reliably
		 * determine if sleeping here is permitted -- see in_atomic().
		 */

		udelay(1);
		raw_spin_lock_irqsave(&report_lock, *flags);
		if (timeout-- < 0) {
			/*
			 * Abort. Reset @other_info->task to NULL, since it
			 * appears the other thread is still going to consume
			 * it. It will result in no verbose info printed for
			 * this task.
			 */
			other_info->task = NULL;
			break;
		}
		/*
		 * If invalid, or @ptr nor @current matches, then @other_info
		 * has been consumed and we may continue. If not, retry.
		 */
	} while (other_info->ai.size && other_info->ai.ptr == ai->ptr &&
		 other_info->task == current);
	if (is_running)
		set_current_state(TASK_RUNNING);
}

/* Populate @other_info; requires that the provided @other_info not in use. */
static void prepare_report_producer(unsigned long *flags,
				    const struct access_info *ai,
				    struct other_info *other_info)
{
	raw_spin_lock_irqsave(&report_lock, *flags);

	/*
	 * The same @other_infos entry cannot be used concurrently, because
	 * there is a one-to-one mapping to watchpoint slots (@watchpoints in
	 * core.c), and a watchpoint is only released for reuse after reporting
	 * is done by the consumer of @other_info. Therefore, it is impossible
	 * for another concurrent prepare_report_producer() to set the same
	 * @other_info, and are guaranteed exclusivity for the @other_infos
	 * entry pointed to by @other_info.
	 *
	 * To check this property holds, size should never be non-zero here,
	 * because every consumer of struct other_info resets size to 0 in
	 * release_report().
	 */
	WARN_ON(other_info->ai.size);

	other_info->ai = *ai;
	other_info->num_stack_entries = stack_trace_save(other_info->stack_entries, NUM_STACK_ENTRIES, 2);

	if (IS_ENABLED(CONFIG_KCSAN_VERBOSE))
		set_other_info_task_blocking(flags, ai, other_info);

	raw_spin_unlock_irqrestore(&report_lock, *flags);
}

/* Awaits producer to fill @other_info and then returns. */
static bool prepare_report_consumer(unsigned long *flags,
				    const struct access_info *ai,
				    struct other_info *other_info)
{

	raw_spin_lock_irqsave(&report_lock, *flags);
	while (!other_info->ai.size) { /* Await valid @other_info. */
		raw_spin_unlock_irqrestore(&report_lock, *flags);
		cpu_relax();
		raw_spin_lock_irqsave(&report_lock, *flags);
	}

	/* Should always have a matching access based on watchpoint encoding. */
	if (WARN_ON(!matching_access((unsigned long)other_info->ai.ptr & WATCHPOINT_ADDR_MASK, other_info->ai.size,
				     (unsigned long)ai->ptr & WATCHPOINT_ADDR_MASK, ai->size)))
		goto discard;

	if (!matching_access((unsigned long)other_info->ai.ptr, other_info->ai.size,
			     (unsigned long)ai->ptr, ai->size)) {
		/*
		 * If the actual accesses to not match, this was a false
		 * positive due to watchpoint encoding.
		 */
		kcsan_counter_inc(KCSAN_COUNTER_ENCODING_FALSE_POSITIVES);
		goto discard;
	}

	return true;

discard:
	release_report(flags, other_info);
	return false;
}

/*
 * Depending on the report type either sets @other_info and returns false, or
 * awaits @other_info and returns true. If @other_info is not required for the
 * report type, simply acquires @report_lock and returns true.
 */
static noinline bool prepare_report(unsigned long *flags,
				    enum kcsan_report_type type,
				    const struct access_info *ai,
				    struct other_info *other_info)
{
	switch (type) {
	case KCSAN_REPORT_CONSUMED_WATCHPOINT:
		prepare_report_producer(flags, ai, other_info);
		return false;
	case KCSAN_REPORT_RACE_SIGNAL:
		return prepare_report_consumer(flags, ai, other_info);
	default:
		/* @other_info not required; just acquire @report_lock. */
		raw_spin_lock_irqsave(&report_lock, *flags);
		return true;
	}
}

void kcsan_report(const volatile void *ptr, size_t size, int access_type,
		  enum kcsan_value_change value_change,
		  enum kcsan_report_type type, int watchpoint_idx)
{
	unsigned long flags = 0;
	const struct access_info ai = {
		.ptr		= ptr,
		.size		= size,
		.access_type	= access_type,
		.task_pid	= in_task() ? task_pid_nr(current) : -1,
		.cpu_id		= raw_smp_processor_id()
	};
	struct other_info *other_info = type == KCSAN_REPORT_RACE_UNKNOWN_ORIGIN
					? NULL : &other_infos[watchpoint_idx];

	kcsan_disable_current();
	if (WARN_ON(watchpoint_idx < 0 || watchpoint_idx >= ARRAY_SIZE(other_infos)))
		goto out;

	/*
	 * With TRACE_IRQFLAGS, lockdep's IRQ trace state becomes corrupted if
	 * we do not turn off lockdep here; this could happen due to recursion
	 * into lockdep via KCSAN if we detect a race in utilities used by
	 * lockdep.
	 */
	lockdep_off();

	if (prepare_report(&flags, type, &ai, other_info)) {
		/*
		 * Never report if value_change is FALSE, only if we it is
		 * either TRUE or MAYBE. In case of MAYBE, further filtering may
		 * be done once we know the full stack trace in print_report().
		 */
		bool reported = value_change != KCSAN_VALUE_CHANGE_FALSE &&
				print_report(value_change, type, &ai, other_info);

		if (reported && panic_on_warn)
			panic("panic_on_warn set ...\n");

		release_report(&flags, other_info);
	}

	lockdep_on();
out:
	kcsan_enable_current();
}