linux/kernel/kcsan/report.c
<<
>>
Prefs
   1// SPDX-License-Identifier: GPL-2.0
   2
   3#include <linux/jiffies.h>
   4#include <linux/kernel.h>
   5#include <linux/lockdep.h>
   6#include <linux/preempt.h>
   7#include <linux/printk.h>
   8#include <linux/sched.h>
   9#include <linux/spinlock.h>
  10#include <linux/stacktrace.h>
  11
  12#include "kcsan.h"
  13#include "encoding.h"
  14
  15/*
  16 * Max. number of stack entries to show in the report.
  17 */
  18#define NUM_STACK_ENTRIES 64
  19
  20/*
  21 * Other thread info: communicated from other racing thread to thread that set
  22 * up the watchpoint, which then prints the complete report atomically. Only
  23 * need one struct, as all threads should to be serialized regardless to print
  24 * the reports, with reporting being in the slow-path.
  25 */
  26static struct {
  27        const volatile void     *ptr;
  28        size_t                  size;
  29        int                     access_type;
  30        int                     task_pid;
  31        int                     cpu_id;
  32        unsigned long           stack_entries[NUM_STACK_ENTRIES];
  33        int                     num_stack_entries;
  34} other_info = { .ptr = NULL };
  35
  36/*
  37 * Information about reported races; used to rate limit reporting.
  38 */
  39struct report_time {
  40        /*
  41         * The last time the race was reported.
  42         */
  43        unsigned long time;
  44
  45        /*
  46         * The frames of the 2 threads; if only 1 thread is known, one frame
  47         * will be 0.
  48         */
  49        unsigned long frame1;
  50        unsigned long frame2;
  51};
  52
  53/*
  54 * Since we also want to be able to debug allocators with KCSAN, to avoid
  55 * deadlock, report_times cannot be dynamically resized with krealloc in
  56 * rate_limit_report.
  57 *
  58 * Therefore, we use a fixed-size array, which at most will occupy a page. This
  59 * still adequately rate limits reports, assuming that a) number of unique data
  60 * races is not excessive, and b) occurrence of unique races within the
  61 * same time window is limited.
  62 */
  63#define REPORT_TIMES_MAX (PAGE_SIZE / sizeof(struct report_time))
  64#define REPORT_TIMES_SIZE                                                      \
  65        (CONFIG_KCSAN_REPORT_ONCE_IN_MS > REPORT_TIMES_MAX ?                   \
  66                 REPORT_TIMES_MAX :                                            \
  67                 CONFIG_KCSAN_REPORT_ONCE_IN_MS)
  68static struct report_time report_times[REPORT_TIMES_SIZE];
  69
  70/*
  71 * This spinlock protects reporting and other_info, since other_info is usually
  72 * required when reporting.
  73 */
  74static DEFINE_SPINLOCK(report_lock);
  75
  76/*
  77 * Checks if the race identified by thread frames frame1 and frame2 has
  78 * been reported since (now - KCSAN_REPORT_ONCE_IN_MS).
  79 */
  80static bool rate_limit_report(unsigned long frame1, unsigned long frame2)
  81{
  82        struct report_time *use_entry = &report_times[0];
  83        unsigned long invalid_before;
  84        int i;
  85
  86        BUILD_BUG_ON(CONFIG_KCSAN_REPORT_ONCE_IN_MS != 0 && REPORT_TIMES_SIZE == 0);
  87
  88        if (CONFIG_KCSAN_REPORT_ONCE_IN_MS == 0)
  89                return false;
  90
  91        invalid_before = jiffies - msecs_to_jiffies(CONFIG_KCSAN_REPORT_ONCE_IN_MS);
  92
  93        /* Check if a matching race report exists. */
  94        for (i = 0; i < REPORT_TIMES_SIZE; ++i) {
  95                struct report_time *rt = &report_times[i];
  96
  97                /*
  98                 * Must always select an entry for use to store info as we
  99                 * cannot resize report_times; at the end of the scan, use_entry
 100                 * will be the oldest entry, which ideally also happened before
 101                 * KCSAN_REPORT_ONCE_IN_MS ago.
 102                 */
 103                if (time_before(rt->time, use_entry->time))
 104                        use_entry = rt;
 105
 106                /*
 107                 * Initially, no need to check any further as this entry as well
 108                 * as following entries have never been used.
 109                 */
 110                if (rt->time == 0)
 111                        break;
 112
 113                /* Check if entry expired. */
 114                if (time_before(rt->time, invalid_before))
 115                        continue; /* before KCSAN_REPORT_ONCE_IN_MS ago */
 116
 117                /* Reported recently, check if race matches. */
 118                if ((rt->frame1 == frame1 && rt->frame2 == frame2) ||
 119                    (rt->frame1 == frame2 && rt->frame2 == frame1))
 120                        return true;
 121        }
 122
 123        use_entry->time = jiffies;
 124        use_entry->frame1 = frame1;
 125        use_entry->frame2 = frame2;
 126        return false;
 127}
 128
 129/*
 130 * Special rules to skip reporting.
 131 */
 132static bool
 133skip_report(enum kcsan_value_change value_change, unsigned long top_frame)
 134{
 135        /* Should never get here if value_change==FALSE. */
 136        WARN_ON_ONCE(value_change == KCSAN_VALUE_CHANGE_FALSE);
 137
 138        /*
 139         * The first call to skip_report always has value_change==TRUE, since we
 140         * cannot know the value written of an instrumented access. For the 2nd
 141         * call there are 6 cases with CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY:
 142         *
 143         * 1. read watchpoint, conflicting write (value_change==TRUE): report;
 144         * 2. read watchpoint, conflicting write (value_change==MAYBE): skip;
 145         * 3. write watchpoint, conflicting write (value_change==TRUE): report;
 146         * 4. write watchpoint, conflicting write (value_change==MAYBE): skip;
 147         * 5. write watchpoint, conflicting read (value_change==MAYBE): skip;
 148         * 6. write watchpoint, conflicting read (value_change==TRUE): report;
 149         *
 150         * Cases 1-4 are intuitive and expected; case 5 ensures we do not report
 151         * data races where the write may have rewritten the same value; case 6
 152         * is possible either if the size is larger than what we check value
 153         * changes for or the access type is KCSAN_ACCESS_ASSERT.
 154         */
 155        if (IS_ENABLED(CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY) &&
 156            value_change == KCSAN_VALUE_CHANGE_MAYBE) {
 157                /*
 158                 * The access is a write, but the data value did not change.
 159                 *
 160                 * We opt-out of this filter for certain functions at request of
 161                 * maintainers.
 162                 */
 163                char buf[64];
 164
 165                snprintf(buf, sizeof(buf), "%ps", (void *)top_frame);
 166                if (!strnstr(buf, "rcu_", sizeof(buf)) &&
 167                    !strnstr(buf, "_rcu", sizeof(buf)) &&
 168                    !strnstr(buf, "_srcu", sizeof(buf)))
 169                        return true;
 170        }
 171
 172        return kcsan_skip_report_debugfs(top_frame);
 173}
 174
 175static const char *get_access_type(int type)
 176{
 177        switch (type) {
 178        case 0:
 179                return "read";
 180        case KCSAN_ACCESS_ATOMIC:
 181                return "read (marked)";
 182        case KCSAN_ACCESS_WRITE:
 183                return "write";
 184        case KCSAN_ACCESS_WRITE | KCSAN_ACCESS_ATOMIC:
 185                return "write (marked)";
 186
 187        /*
 188         * ASSERT variants:
 189         */
 190        case KCSAN_ACCESS_ASSERT:
 191        case KCSAN_ACCESS_ASSERT | KCSAN_ACCESS_ATOMIC:
 192                return "assert no writes";
 193        case KCSAN_ACCESS_ASSERT | KCSAN_ACCESS_WRITE:
 194        case KCSAN_ACCESS_ASSERT | KCSAN_ACCESS_WRITE | KCSAN_ACCESS_ATOMIC:
 195                return "assert no accesses";
 196
 197        default:
 198                BUG();
 199        }
 200}
 201
 202static const char *get_bug_type(int type)
 203{
 204        return (type & KCSAN_ACCESS_ASSERT) != 0 ? "assert: race" : "data-race";
 205}
 206
 207/* Return thread description: in task or interrupt. */
 208static const char *get_thread_desc(int task_id)
 209{
 210        if (task_id != -1) {
 211                static char buf[32]; /* safe: protected by report_lock */
 212
 213                snprintf(buf, sizeof(buf), "task %i", task_id);
 214                return buf;
 215        }
 216        return "interrupt";
 217}
 218
 219/* Helper to skip KCSAN-related functions in stack-trace. */
 220static int get_stack_skipnr(unsigned long stack_entries[], int num_entries)
 221{
 222        char buf[64];
 223        int skip = 0;
 224
 225        for (; skip < num_entries; ++skip) {
 226                snprintf(buf, sizeof(buf), "%ps", (void *)stack_entries[skip]);
 227                if (!strnstr(buf, "csan_", sizeof(buf)) &&
 228                    !strnstr(buf, "tsan_", sizeof(buf)) &&
 229                    !strnstr(buf, "_once_size", sizeof(buf))) {
 230                        break;
 231                }
 232        }
 233        return skip;
 234}
 235
 236/* Compares symbolized strings of addr1 and addr2. */
 237static int sym_strcmp(void *addr1, void *addr2)
 238{
 239        char buf1[64];
 240        char buf2[64];
 241
 242        snprintf(buf1, sizeof(buf1), "%pS", addr1);
 243        snprintf(buf2, sizeof(buf2), "%pS", addr2);
 244
 245        return strncmp(buf1, buf2, sizeof(buf1));
 246}
 247
 248/*
 249 * Returns true if a report was generated, false otherwise.
 250 */
 251static bool print_report(const volatile void *ptr, size_t size, int access_type,
 252                         enum kcsan_value_change value_change, int cpu_id,
 253                         enum kcsan_report_type type)
 254{
 255        unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 };
 256        int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1);
 257        int skipnr = get_stack_skipnr(stack_entries, num_stack_entries);
 258        unsigned long this_frame = stack_entries[skipnr];
 259        unsigned long other_frame = 0;
 260        int other_skipnr = 0; /* silence uninit warnings */
 261
 262        /*
 263         * Must check report filter rules before starting to print.
 264         */
 265        if (skip_report(KCSAN_VALUE_CHANGE_TRUE, stack_entries[skipnr]))
 266                return false;
 267
 268        if (type == KCSAN_REPORT_RACE_SIGNAL) {
 269                other_skipnr = get_stack_skipnr(other_info.stack_entries,
 270                                                other_info.num_stack_entries);
 271                other_frame = other_info.stack_entries[other_skipnr];
 272
 273                /* @value_change is only known for the other thread */
 274                if (skip_report(value_change, other_frame))
 275                        return false;
 276        }
 277
 278        if (rate_limit_report(this_frame, other_frame))
 279                return false;
 280
 281        /* Print report header. */
 282        pr_err("==================================================================\n");
 283        switch (type) {
 284        case KCSAN_REPORT_RACE_SIGNAL: {
 285                int cmp;
 286
 287                /*
 288                 * Order functions lexographically for consistent bug titles.
 289                 * Do not print offset of functions to keep title short.
 290                 */
 291                cmp = sym_strcmp((void *)other_frame, (void *)this_frame);
 292                pr_err("BUG: KCSAN: %s in %ps / %ps\n",
 293                       get_bug_type(access_type | other_info.access_type),
 294                       (void *)(cmp < 0 ? other_frame : this_frame),
 295                       (void *)(cmp < 0 ? this_frame : other_frame));
 296        } break;
 297
 298        case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN:
 299                pr_err("BUG: KCSAN: %s in %pS\n", get_bug_type(access_type),
 300                       (void *)this_frame);
 301                break;
 302
 303        default:
 304                BUG();
 305        }
 306
 307        pr_err("\n");
 308
 309        /* Print information about the racing accesses. */
 310        switch (type) {
 311        case KCSAN_REPORT_RACE_SIGNAL:
 312                pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n",
 313                       get_access_type(other_info.access_type), other_info.ptr,
 314                       other_info.size, get_thread_desc(other_info.task_pid),
 315                       other_info.cpu_id);
 316
 317                /* Print the other thread's stack trace. */
 318                stack_trace_print(other_info.stack_entries + other_skipnr,
 319                                  other_info.num_stack_entries - other_skipnr,
 320                                  0);
 321
 322                pr_err("\n");
 323                pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n",
 324                       get_access_type(access_type), ptr, size,
 325                       get_thread_desc(in_task() ? task_pid_nr(current) : -1),
 326                       cpu_id);
 327                break;
 328
 329        case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN:
 330                pr_err("race at unknown origin, with %s to 0x%px of %zu bytes by %s on cpu %i:\n",
 331                       get_access_type(access_type), ptr, size,
 332                       get_thread_desc(in_task() ? task_pid_nr(current) : -1),
 333                       cpu_id);
 334                break;
 335
 336        default:
 337                BUG();
 338        }
 339        /* Print stack trace of this thread. */
 340        stack_trace_print(stack_entries + skipnr, num_stack_entries - skipnr,
 341                          0);
 342
 343        /* Print report footer. */
 344        pr_err("\n");
 345        pr_err("Reported by Kernel Concurrency Sanitizer on:\n");
 346        dump_stack_print_info(KERN_DEFAULT);
 347        pr_err("==================================================================\n");
 348
 349        return true;
 350}
 351
 352static void release_report(unsigned long *flags, enum kcsan_report_type type)
 353{
 354        if (type == KCSAN_REPORT_RACE_SIGNAL)
 355                other_info.ptr = NULL; /* mark for reuse */
 356
 357        spin_unlock_irqrestore(&report_lock, *flags);
 358}
 359
 360/*
 361 * Depending on the report type either sets other_info and returns false, or
 362 * acquires the matching other_info and returns true. If other_info is not
 363 * required for the report type, simply acquires report_lock and returns true.
 364 */
 365static bool prepare_report(unsigned long *flags, const volatile void *ptr,
 366                           size_t size, int access_type, int cpu_id,
 367                           enum kcsan_report_type type)
 368{
 369        if (type != KCSAN_REPORT_CONSUMED_WATCHPOINT &&
 370            type != KCSAN_REPORT_RACE_SIGNAL) {
 371                /* other_info not required; just acquire report_lock */
 372                spin_lock_irqsave(&report_lock, *flags);
 373                return true;
 374        }
 375
 376retry:
 377        spin_lock_irqsave(&report_lock, *flags);
 378
 379        switch (type) {
 380        case KCSAN_REPORT_CONSUMED_WATCHPOINT:
 381                if (other_info.ptr != NULL)
 382                        break; /* still in use, retry */
 383
 384                other_info.ptr                  = ptr;
 385                other_info.size                 = size;
 386                other_info.access_type          = access_type;
 387                other_info.task_pid             = in_task() ? task_pid_nr(current) : -1;
 388                other_info.cpu_id               = cpu_id;
 389                other_info.num_stack_entries    = stack_trace_save(other_info.stack_entries, NUM_STACK_ENTRIES, 1);
 390
 391                spin_unlock_irqrestore(&report_lock, *flags);
 392
 393                /*
 394                 * The other thread will print the summary; other_info may now
 395                 * be consumed.
 396                 */
 397                return false;
 398
 399        case KCSAN_REPORT_RACE_SIGNAL:
 400                if (other_info.ptr == NULL)
 401                        break; /* no data available yet, retry */
 402
 403                /*
 404                 * First check if this is the other_info we are expecting, i.e.
 405                 * matches based on how watchpoint was encoded.
 406                 */
 407                if (!matching_access((unsigned long)other_info.ptr &
 408                                             WATCHPOINT_ADDR_MASK,
 409                                     other_info.size,
 410                                     (unsigned long)ptr & WATCHPOINT_ADDR_MASK,
 411                                     size))
 412                        break; /* mismatching watchpoint, retry */
 413
 414                if (!matching_access((unsigned long)other_info.ptr,
 415                                     other_info.size, (unsigned long)ptr,
 416                                     size)) {
 417                        /*
 418                         * If the actual accesses to not match, this was a false
 419                         * positive due to watchpoint encoding.
 420                         */
 421                        kcsan_counter_inc(
 422                                KCSAN_COUNTER_ENCODING_FALSE_POSITIVES);
 423
 424                        /* discard this other_info */
 425                        release_report(flags, KCSAN_REPORT_RACE_SIGNAL);
 426                        return false;
 427                }
 428
 429                access_type |= other_info.access_type;
 430                if ((access_type & KCSAN_ACCESS_WRITE) == 0) {
 431                        /*
 432                         * While the address matches, this is not the other_info
 433                         * from the thread that consumed our watchpoint, since
 434                         * neither this nor the access in other_info is a write.
 435                         * It is invalid to continue with the report, since we
 436                         * only have information about reads.
 437                         *
 438                         * This can happen due to concurrent races on the same
 439                         * address, with at least 4 threads. To avoid locking up
 440                         * other_info and all other threads, we have to consume
 441                         * it regardless.
 442                         *
 443                         * A concrete case to illustrate why we might lock up if
 444                         * we do not consume other_info:
 445                         *
 446                         *   We have 4 threads, all accessing the same address
 447                         *   (or matching address ranges). Assume the following
 448                         *   watcher and watchpoint consumer pairs:
 449                         *   write1-read1, read2-write2. The first to populate
 450                         *   other_info is write2, however, write1 consumes it,
 451                         *   resulting in a report of write1-write2. This report
 452                         *   is valid, however, now read1 populates other_info;
 453                         *   read2-read1 is an invalid conflict, yet, no other
 454                         *   conflicting access is left. Therefore, we must
 455                         *   consume read1's other_info.
 456                         *
 457                         * Since this case is assumed to be rare, it is
 458                         * reasonable to omit this report: one of the other
 459                         * reports includes information about the same shared
 460                         * data, and at this point the likelihood that we
 461                         * re-report the same race again is high.
 462                         */
 463                        release_report(flags, KCSAN_REPORT_RACE_SIGNAL);
 464                        return false;
 465                }
 466
 467                /*
 468                 * Matching & usable access in other_info: keep other_info_lock
 469                 * locked, as this thread consumes it to print the full report;
 470                 * unlocked in release_report.
 471                 */
 472                return true;
 473
 474        default:
 475                BUG();
 476        }
 477
 478        spin_unlock_irqrestore(&report_lock, *flags);
 479
 480        goto retry;
 481}
 482
 483void kcsan_report(const volatile void *ptr, size_t size, int access_type,
 484                  enum kcsan_value_change value_change, int cpu_id,
 485                  enum kcsan_report_type type)
 486{
 487        unsigned long flags = 0;
 488
 489        /*
 490         * With TRACE_IRQFLAGS, lockdep's IRQ trace state becomes corrupted if
 491         * we do not turn off lockdep here; this could happen due to recursion
 492         * into lockdep via KCSAN if we detect a race in utilities used by
 493         * lockdep.
 494         */
 495        lockdep_off();
 496
 497        kcsan_disable_current();
 498        if (prepare_report(&flags, ptr, size, access_type, cpu_id, type)) {
 499                /*
 500                 * Never report if value_change is FALSE, only if we it is
 501                 * either TRUE or MAYBE. In case of MAYBE, further filtering may
 502                 * be done once we know the full stack trace in print_report().
 503                 */
 504                bool reported = value_change != KCSAN_VALUE_CHANGE_FALSE &&
 505                                print_report(ptr, size, access_type, value_change, cpu_id, type);
 506
 507                if (reported && panic_on_warn)
 508                        panic("panic_on_warn set ...\n");
 509
 510                release_report(&flags, type);
 511        }
 512        kcsan_enable_current();
 513
 514        lockdep_on();
 515}
 516