kernel/printk/printk_safe.c

   1 /*
   2  * printk_safe.c - Safe printk for printk-deadlock-prone contexts
   3  *
   4  * This program is free software; you can redistribute it and/or
   5  * modify it under the terms of the GNU General Public License
   6  * as published by the Free Software Foundation; either version 2
   7  * of the License, or (at your option) any later version.
   8  *
   9  * This program is distributed in the hope that it will be useful,
  10  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  11  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12  * GNU General Public License for more details.
  13  *
  14  * You should have received a copy of the GNU General Public License
  15  * along with this program; if not, see <http://www.gnu.org/licenses/>.
  16  */
  17
  18 #include <linux/preempt.h>
  19 #include <linux/spinlock.h>
  20 #include <linux/debug_locks.h>
  21 #include <linux/smp.h>
  22 #include <linux/cpumask.h>
  23 #include <linux/irq_work.h>
  24 #include <linux/printk.h>
  25
  26 #include "internal.h"
  27
  28 /*
  29  * printk() could not take logbuf_lock in NMI context. Instead,
  30  * it uses an alternative implementation that temporary stores
  31  * the strings into a per-CPU buffer. The content of the buffer
  32  * is later flushed into the main ring buffer via IRQ work.
  33  *
  34  * The alternative implementation is chosen transparently
  35  * by examinig current printk() context mask stored in @printk_context
  36  * per-CPU variable.
  37  *
  38  * The implementation allows to flush the strings also from another CPU.
  39  * There are situations when we want to make sure that all buffers
  40  * were handled or when IRQs are blocked.
  41  */
  42 static int printk_safe_irq_ready;
  43
  44 #define SAFE_LOG_BUF_LEN ((1 << CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT) -     \
  45                                 sizeof(atomic_t) -                      \
  46                                 sizeof(atomic_t) -                      \
  47                                 sizeof(struct irq_work))
  48
  49 struct printk_safe_seq_buf {
  50         atomic_t                len;    /* length of written data */
  51         atomic_t                message_lost;
  52         struct irq_work         work;   /* IRQ work that flushes the buffer */
  53         unsigned char           buffer[SAFE_LOG_BUF_LEN];
  54 };
  55
  56 static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
  57 static DEFINE_PER_CPU(int, printk_context);
  58
  59 static DEFINE_RAW_SPINLOCK(safe_read_lock);
  60
  61 #ifdef CONFIG_PRINTK_NMI
  62 static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
  63 #endif
  64
  65 /* Get flushed in a more safe context. */
  66 static void queue_flush_work(struct printk_safe_seq_buf *s)
  67 {
  68         if (printk_safe_irq_ready) {
  69                 /* Make sure that IRQ work is really initialized. */
  70                 smp_rmb();
  71                 irq_work_queue(&s->work);
  72         }
  73 }
  74
  75 /*
  76  * Add a message to per-CPU context-dependent buffer. NMI and printk-safe
  77  * have dedicated buffers, because otherwise printk-safe preempted by
  78  * NMI-printk would have overwritten the NMI messages.
  79  *
  80  * The messages are fushed from irq work (or from panic()), possibly,
  81  * from other CPU, concurrently with printk_safe_log_store(). Should this
  82  * happen, printk_safe_log_store() will notice the buffer->len mismatch
  83  * and repeat the write.
  84  */
  85 static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s,
  86                                                 const char *fmt, va_list args)
  87 {
  88         int add;
  89         size_t len;
  90         va_list ap;
  91
  92 again:
  93         len = atomic_read(&s->len);
  94
  95         /* The trailing '\0' is not counted into len. */
  96         if (len >= sizeof(s->buffer) - 1) {
  97                 atomic_inc(&s->message_lost);
  98                 queue_flush_work(s);
  99                 return 0;
 100         }
 101
 102         /*
 103          * Make sure that all old data have been read before the buffer
 104          * was reset. This is not needed when we just append data.
 105          */
 106         if (!len)
 107                 smp_rmb();
 108
 109         va_copy(ap, args);
 110         add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len, fmt, ap);
 111         va_end(ap);
 112         if (!add)
 113                 return 0;
 114
 115         /*
 116          * Do it once again if the buffer has been flushed in the meantime.
 117          * Note that atomic_cmpxchg() is an implicit memory barrier that
 118          * makes sure that the data were written before updating s->len.
 119          */
 120         if (atomic_cmpxchg(&s->len, len, len + add) != len)
 121                 goto again;
 122
 123         queue_flush_work(s);
 124         return add;
 125 }
 126
 127 static inline void printk_safe_flush_line(const char *text, int len)
 128 {
 129         /*
 130          * Avoid any console drivers calls from here, because we may be
 131          * in NMI or printk_safe context (when in panic). The messages
 132          * must go only into the ring buffer at this stage.  Consoles will
 133          * get explicitly called later when a crashdump is not generated.
 134          */
 135         printk_deferred("%.*s", len, text);
 136 }
 137
 138 /* printk part of the temporary buffer line by line */
 139 static int printk_safe_flush_buffer(const char *start, size_t len)
 140 {
 141         const char *c, *end;
 142         bool header;
 143
 144         c = start;
 145         end = start + len;
 146         header = true;
 147
 148         /* Print line by line. */
 149         while (c < end) {
 150                 if (*c == '\n') {
 151                         printk_safe_flush_line(start, c - start + 1);
 152                         start = ++c;
 153                         header = true;
 154                         continue;
 155                 }
 156
 157                 /* Handle continuous lines or missing new line. */
 158                 if ((c + 1 < end) && printk_get_level(c)) {
 159                         if (header) {
 160                                 c = printk_skip_level(c);
 161                                 continue;
 162                         }
 163
 164                         printk_safe_flush_line(start, c - start);
 165                         start = c++;
 166                         header = true;
 167                         continue;
 168                 }
 169
 170                 header = false;
 171                 c++;
 172         }
 173
 174         /* Check if there was a partial line. Ignore pure header. */
 175         if (start < end && !header) {
 176                 static const char newline[] = KERN_CONT "\n";
 177
 178                 printk_safe_flush_line(start, end - start);
 179                 printk_safe_flush_line(newline, strlen(newline));
 180         }
 181
 182         return len;
 183 }
 184
 185 static void report_message_lost(struct printk_safe_seq_buf *s)
 186 {
 187         int lost = atomic_xchg(&s->message_lost, 0);
 188
 189         if (lost)
 190                 printk_deferred("Lost %d message(s)!\n", lost);
 191 }
 192
 193 /*
 194  * Flush data from the associated per-CPU buffer. The function
 195  * can be called either via IRQ work or independently.
 196  */
 197 static void __printk_safe_flush(struct irq_work *work)
 198 {
 199         struct printk_safe_seq_buf *s =
 200                 container_of(work, struct printk_safe_seq_buf, work);
 201         unsigned long flags;
 202         size_t len;
 203         int i;
 204
 205         /*
 206          * The lock has two functions. First, one reader has to flush all
 207          * available message to make the lockless synchronization with
 208          * writers easier. Second, we do not want to mix messages from
 209          * different CPUs. This is especially important when printing
 210          * a backtrace.
 211          */
 212         raw_spin_lock_irqsave(&safe_read_lock, flags);
 213
 214         i = 0;
 215 more:
 216         len = atomic_read(&s->len);
 217
 218         /*
 219          * This is just a paranoid check that nobody has manipulated
 220          * the buffer an unexpected way. If we printed something then
 221          * @len must only increase. Also it should never overflow the
 222          * buffer size.
 223          */
 224         if ((i && i >= len) || len > sizeof(s->buffer)) {
 225                 const char *msg = "printk_safe_flush: internal error\n";
 226
 227                 printk_safe_flush_line(msg, strlen(msg));
 228                 len = 0;
 229         }
 230
 231         if (!len)
 232                 goto out; /* Someone else has already flushed the buffer. */
 233
 234         /* Make sure that data has been written up to the @len */
 235         smp_rmb();
 236         i += printk_safe_flush_buffer(s->buffer + i, len - i);
 237
 238         /*
 239          * Check that nothing has got added in the meantime and truncate
 240          * the buffer. Note that atomic_cmpxchg() is an implicit memory
 241          * barrier that makes sure that the data were copied before
 242          * updating s->len.
 243          */
 244         if (atomic_cmpxchg(&s->len, len, 0) != len)
 245                 goto more;
 246
 247 out:
 248         report_message_lost(s);
 249         raw_spin_unlock_irqrestore(&safe_read_lock, flags);
 250 }
 251
 252 /**
 253  * printk_safe_flush - flush all per-cpu nmi buffers.
 254  *
 255  * The buffers are flushed automatically via IRQ work. This function
 256  * is useful only when someone wants to be sure that all buffers have
 257  * been flushed at some point.
 258  */
 259 void printk_safe_flush(void)
 260 {
 261         int cpu;
 262
 263         for_each_possible_cpu(cpu) {
 264 #ifdef CONFIG_PRINTK_NMI
 265                 __printk_safe_flush(&per_cpu(nmi_print_seq, cpu).work);
 266 #endif
 267                 __printk_safe_flush(&per_cpu(safe_print_seq, cpu).work);
 268         }
 269 }
 270
 271 /**
 272  * printk_safe_flush_on_panic - flush all per-cpu nmi buffers when the system
 273  *      goes down.
 274  *
 275  * Similar to printk_safe_flush() but it can be called even in NMI context when
 276  * the system goes down. It does the best effort to get NMI messages into
 277  * the main ring buffer.
 278  *
 279  * Note that it could try harder when there is only one CPU online.
 280  */
 281 void printk_safe_flush_on_panic(void)
 282 {
 283         /*
 284          * Make sure that we could access the main ring buffer.
 285          * Do not risk a double release when more CPUs are up.
 286          */
 287         if (raw_spin_is_locked(&logbuf_lock)) {
 288                 if (num_online_cpus() > 1)
 289                         return;
 290
 291                 debug_locks_off();
 292                 raw_spin_lock_init(&logbuf_lock);
 293         }
 294
 295         if (raw_spin_is_locked(&safe_read_lock)) {
 296                 if (num_online_cpus() > 1)
 297                         return;
 298
 299                 debug_locks_off();
 300                 raw_spin_lock_init(&safe_read_lock);
 301         }
 302
 303         printk_safe_flush();
 304 }
 305
 306 #ifdef CONFIG_PRINTK_NMI
 307 /*
 308  * Safe printk() for NMI context. It uses a per-CPU buffer to
 309  * store the message. NMIs are not nested, so there is always only
 310  * one writer running. But the buffer might get flushed from another
 311  * CPU, so we need to be careful.
 312  */
 313 static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args)
 314 {
 315         struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
 316
 317         return printk_safe_log_store(s, fmt, args);
 318 }
 319
 320 void notrace printk_nmi_enter(void)
 321 {
 322         this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
 323 }
 324
 325 void notrace printk_nmi_exit(void)
 326 {
 327         this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK);
 328 }
 329
 330 /*
 331  * Marks a code that might produce many messages in NMI context
 332  * and the risk of losing them is more critical than eventual
 333  * reordering.
 334  *
 335  * It has effect only when called in NMI context. Then printk()
 336  * will try to store the messages into the main logbuf directly
 337  * and use the per-CPU buffers only as a fallback when the lock
 338  * is not available.
 339  */
 340 void printk_nmi_direct_enter(void)
 341 {
 342         if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
 343                 this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK);
 344 }
 345
 346 void printk_nmi_direct_exit(void)
 347 {
 348         this_cpu_and(printk_context, ~PRINTK_NMI_DIRECT_CONTEXT_MASK);
 349 }
 350
 351 #else
 352
 353 static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args)
 354 {
 355         return 0;
 356 }
 357
 358 #endif /* CONFIG_PRINTK_NMI */
 359
 360 /*
 361  * Lock-less printk(), to avoid deadlocks should the printk() recurse
 362  * into itself. It uses a per-CPU buffer to store the message, just like
 363  * NMI.
 364  */
 365 static __printf(1, 0) int vprintk_safe(const char *fmt, va_list args)
 366 {
 367         struct printk_safe_seq_buf *s = this_cpu_ptr(&safe_print_seq);
 368
 369         return printk_safe_log_store(s, fmt, args);
 370 }
 371
 372 /* Can be preempted by NMI. */
 373 void __printk_safe_enter(void)
 374 {
 375         this_cpu_inc(printk_context);
 376 }
 377
 378 /* Can be preempted by NMI. */
 379 void __printk_safe_exit(void)
 380 {
 381         this_cpu_dec(printk_context);
 382 }
 383
 384 __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 385 {
 386         /*
 387          * Try to use the main logbuf even in NMI. But avoid calling console
 388          * drivers that might have their own locks.
 389          */
 390         if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
 391             raw_spin_trylock(&logbuf_lock)) {
 392                 int len;
 393
 394                 len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
 395                 raw_spin_unlock(&logbuf_lock);
 396                 defer_console_output();
 397                 return len;
 398         }
 399
 400         /* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
 401         if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
 402                 return vprintk_nmi(fmt, args);
 403
 404         /* Use extra buffer to prevent a recursion deadlock in safe mode. */
 405         if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
 406                 return vprintk_safe(fmt, args);
 407
 408         /* No obstacles. */
 409         return vprintk_default(fmt, args);
 410 }
 411
 412 void __init printk_safe_init(void)
 413 {
 414         int cpu;
 415
 416         for_each_possible_cpu(cpu) {
 417                 struct printk_safe_seq_buf *s;
 418
 419                 s = &per_cpu(safe_print_seq, cpu);
 420                 init_irq_work(&s->work, __printk_safe_flush);
 421
 422 #ifdef CONFIG_PRINTK_NMI
 423                 s = &per_cpu(nmi_print_seq, cpu);
 424                 init_irq_work(&s->work, __printk_safe_flush);
 425 #endif
 426         }
 427
 428         /* Make sure that IRQ works are initialized before enabling. */
 429         smp_wmb();
 430         printk_safe_irq_ready = 1;
 431
 432         /* Flush pending messages that did not have scheduled IRQ works. */
 433         printk_safe_flush();
 434 }