Merge tag 'printk-for-4.19' of git://git.kernel.org/pub/scm/linux/kernel/git/pmladek/printk

Pull printk updates from Petr Mladek:

 - Different vendors have a different expectation about a console
   quietness. Make it configurable to reduce bike-shedding about the
   upstream default

 - Decide about the message visibility when the message is stored. It
   avoids races caused by a delayed console handling

 - Always store printk() messages into the per-CPU buffers again in NMI.
   The only exception is when flushing trace log in panic(). There the
   risk of loosing messages is worth an eventual reordering

 - Handle invalid %pO printf modifiers correctly

 - Better handle %p printf modifier tests before crng is initialized

 - Some clean up

* tag 'printk-for-4.19' of git://git.kernel.org/pub/scm/linux/kernel/git/pmladek/printk:
  lib/vsprintf: Do not handle %pO[^F] as %px
  printk: Fix warning about unused suppress_message_printing
  printk/nmi: Prevent deadlock when accessing the main log buffer in NMI
  printk: Create helper function to queue deferred console handling
  printk: Split the code for storing a message into the log buffer
  printk: Clean up syslog_print_all()
  printk: Remove unnecessary kmalloc() from syslog during clear
  printk: Make CONSOLE_LOGLEVEL_QUIET configurable
  printk: make sure to print log on console.
  lib/test_printf.c: accept "ptrval" as valid result for plain 'p' tests

9 files changed, 189 insertions, 112 deletions

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 6d7e800affd8..cf3eccfe1543 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -50,15 +50,15 @@ static inline const char *printk_skip_headers(const char *buffer)
 /* We show everything that is MORE important than this.. */
 #define CONSOLE_LOGLEVEL_SILENT  0 /* Mum's the word */
 #define CONSOLE_LOGLEVEL_MIN     1 /* Minimum loglevel we let people use */
-#define CONSOLE_LOGLEVEL_QUIET   4 /* Shhh ..., when booted with "quiet" */
 #define CONSOLE_LOGLEVEL_DEBUG  10 /* issue debug messages */
 #define CONSOLE_LOGLEVEL_MOTORMOUTH 15  /* You can't shut this one up */
 
 /*
- * Default used to be hard-coded at 7, we're now allowing it to be set from
- * kernel config.
+ * Default used to be hard-coded at 7, quiet used to be hardcoded at 4,
+ * we're now allowing both to be set from kernel config.
  */
 #define CONSOLE_LOGLEVEL_DEFAULT CONFIG_CONSOLE_LOGLEVEL_DEFAULT
+#define CONSOLE_LOGLEVEL_QUIET   CONFIG_CONSOLE_LOGLEVEL_QUIET
 
 extern int console_printk[];
 
@@ -148,9 +148,13 @@ void early_printk(const char *s, ...) { }
 #ifdef CONFIG_PRINTK_NMI
 extern void printk_nmi_enter(void);
 extern void printk_nmi_exit(void);
+extern void printk_nmi_direct_enter(void);
+extern void printk_nmi_direct_exit(void);
 #else
 static inline void printk_nmi_enter(void) { }
 static inline void printk_nmi_exit(void) { }
+static inline void printk_nmi_direct_enter(void) { }
+static inline void printk_nmi_direct_exit(void) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 2a7d04049af4..0f1898820cba 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -19,11 +19,16 @@
 #ifdef CONFIG_PRINTK
 
 #define PRINTK_SAFE_CONTEXT_MASK         0x3fffffff
-#define PRINTK_NMI_DEFERRED_CONTEXT_MASK 0x40000000
+#define PRINTK_NMI_DIRECT_CONTEXT_MASK   0x40000000
 #define PRINTK_NMI_CONTEXT_MASK          0x80000000
 
 extern raw_spinlock_t logbuf_lock;
 
+__printf(5, 0)
+int vprintk_store(int facility, int level,
+                  const char *dict, size_t dictlen,
+                  const char *fmt, va_list args);
+
 __printf(1, 0) int vprintk_default(const char *fmt, va_list args);
 __printf(1, 0) int vprintk_deferred(const char *fmt, va_list args);
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args);
@@ -54,6 +59,8 @@ void __printk_safe_exit(void);
                 local_irq_enable();             \
         } while (0)
 
+void defer_console_output(void);
+
 #else
 
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 247808333ba4..9a63aeeaaf5d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -349,7 +349,7 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
  */
 
 enum log_flags {
-        LOG_NOCONS      = 1,    /* already flushed, do not print to console */
+        LOG_NOCONS      = 1,    /* suppress print, do not print to console */
         LOG_NEWLINE     = 2,    /* text ended with a newline */
         LOG_PREFIX      = 4,    /* text started with a prefix */
         LOG_CONT        = 8,    /* text is a fragment of a continuation line */
@@ -1352,71 +1352,68 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 {
         char *text;
         int len = 0;
+        u64 next_seq;
+        u64 seq;
+        u32 idx;
 
         text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
         if (!text)
                 return -ENOMEM;
 
         logbuf_lock_irq();
-        if (buf) {
-                u64 next_seq;
-                u64 seq;
-                u32 idx;
+        /*
+         * Find first record that fits, including all following records,
+         * into the user-provided buffer for this dump.
+         */
+        seq = clear_seq;
+        idx = clear_idx;
+        while (seq < log_next_seq) {
+                struct printk_log *msg = log_from_idx(idx);
 
-                /*
-                 * Find first record that fits, including all following records,
-                 * into the user-provided buffer for this dump.
-                 */
-                seq = clear_seq;
-                idx = clear_idx;
-                while (seq < log_next_seq) {
-                        struct printk_log *msg = log_from_idx(idx);
-
-                        len += msg_print_text(msg, true, NULL, 0);
-                        idx = log_next(idx);
-                        seq++;
-                }
+                len += msg_print_text(msg, true, NULL, 0);
+                idx = log_next(idx);
+                seq++;
+        }
 
-                /* move first record forward until length fits into the buffer */
-                seq = clear_seq;
-                idx = clear_idx;
-                while (len > size && seq < log_next_seq) {
-                        struct printk_log *msg = log_from_idx(idx);
+        /* move first record forward until length fits into the buffer */
+        seq = clear_seq;
+        idx = clear_idx;
+        while (len > size && seq < log_next_seq) {
+                struct printk_log *msg = log_from_idx(idx);
 
-                        len -= msg_print_text(msg, true, NULL, 0);
-                        idx = log_next(idx);
-                        seq++;
-                }
+                len -= msg_print_text(msg, true, NULL, 0);
+                idx = log_next(idx);
+                seq++;
+        }
 
-                /* last message fitting into this dump */
-                next_seq = log_next_seq;
+        /* last message fitting into this dump */
+        next_seq = log_next_seq;
 
-                len = 0;
-                while (len >= 0 && seq < next_seq) {
-                        struct printk_log *msg = log_from_idx(idx);
-                        int textlen;
+        len = 0;
+        while (len >= 0 && seq < next_seq) {
+                struct printk_log *msg = log_from_idx(idx);
+                int textlen;
 
-                        textlen = msg_print_text(msg, true, text,
-                                                 LOG_LINE_MAX + PREFIX_MAX);
-                        if (textlen < 0) {
-                                len = textlen;
-                                break;
-                        }
-                        idx = log_next(idx);
-                        seq++;
+                textlen = msg_print_text(msg, true, text,
+                                         LOG_LINE_MAX + PREFIX_MAX);
+                if (textlen < 0) {
+                        len = textlen;
+                        break;
+                }
+                idx = log_next(idx);
+                seq++;
 
-                        logbuf_unlock_irq();
-                        if (copy_to_user(buf + len, text, textlen))
-                                len = -EFAULT;
-                        else
-                                len += textlen;
-                        logbuf_lock_irq();
-
-                        if (seq < log_first_seq) {
-                                /* messages are gone, move to next one */
-                                seq = log_first_seq;
-                                idx = log_first_idx;
-                        }
+                logbuf_unlock_irq();
+                if (copy_to_user(buf + len, text, textlen))
+                        len = -EFAULT;
+                else
+                        len += textlen;
+                logbuf_lock_irq();
+
+                if (seq < log_first_seq) {
+                        /* messages are gone, move to next one */
+                        seq = log_first_seq;
+                        idx = log_first_idx;
                 }
         }
 
@@ -1430,6 +1427,14 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
         return len;
 }
 
+static void syslog_clear(void)
+{
+        logbuf_lock_irq();
+        clear_seq = log_next_seq;
+        clear_idx = log_next_idx;
+        logbuf_unlock_irq();
+}
+
 int do_syslog(int type, char __user *buf, int len, int source)
 {
         bool clear = false;
@@ -1474,7 +1479,7 @@ int do_syslog(int type, char __user *buf, int len, int source)
                 break;
         /* Clear ring buffer */
         case SYSLOG_ACTION_CLEAR:
-                syslog_print_all(NULL, 0, true);
+                syslog_clear();
                 break;
         /* Disable logging to console */
         case SYSLOG_ACTION_CONSOLE_OFF:
@@ -1824,28 +1829,16 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
         return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
-asmlinkage int vprintk_emit(int facility, int level,
-                            const char *dict, size_t dictlen,
-                            const char *fmt, va_list args)
+/* Must be called under logbuf_lock. */
+int vprintk_store(int facility, int level,
+                  const char *dict, size_t dictlen,
+                  const char *fmt, va_list args)
 {
         static char textbuf[LOG_LINE_MAX];
         char *text = textbuf;
         size_t text_len;
         enum log_flags lflags = 0;
-        unsigned long flags;
-        int printed_len;
-        bool in_sched = false;
 
-        if (level == LOGLEVEL_SCHED) {
-                level = LOGLEVEL_DEFAULT;
-                in_sched = true;
-        }
-
-        boot_delay_msec(level);
-        printk_delay();
-
-        /* This stops the holder of console_sem just where we want him */
-        logbuf_lock_irqsave(flags);
         /*
          * The printf needs to come first; we need the syslog
          * prefix which might be passed-in as a parameter.
@@ -1886,8 +1879,32 @@ asmlinkage int vprintk_emit(int facility, int level,
         if (dict)
                 lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-        printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
+        if (suppress_message_printing(level))
+                lflags |= LOG_NOCONS;
+
+        return log_output(facility, level, lflags,
+                          dict, dictlen, text, text_len);
+}
+
+asmlinkage int vprintk_emit(int facility, int level,
+                            const char *dict, size_t dictlen,
+                            const char *fmt, va_list args)
+{
+        int printed_len;
+        bool in_sched = false;
+        unsigned long flags;
+
+        if (level == LOGLEVEL_SCHED) {
+                level = LOGLEVEL_DEFAULT;
+                in_sched = true;
+        }
 
+        boot_delay_msec(level);
+        printk_delay();
+
+        /* This stops the holder of console_sem just where we want him */
+        logbuf_lock_irqsave(flags);
+        printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
         logbuf_unlock_irqrestore(flags);
 
         /* If called from the scheduler, we can not call up(). */
@@ -2013,7 +2030,6 @@ static void call_console_drivers(const char *ext_text, size_t ext_len,
                                  const char *text, size_t len) {}
 static size_t msg_print_text(const struct printk_log *msg,
                              bool syslog, char *buf, size_t size) { return 0; }
-static bool suppress_message_printing(int level) { return false; }
 
 #endif /* CONFIG_PRINTK */
 
@@ -2349,11 +2365,10 @@ skip:
                         break;
 
                 msg = log_from_idx(console_idx);
-                if (suppress_message_printing(msg->level)) {
+                if (msg->flags & LOG_NOCONS) {
                         /*
-                         * Skip record we have buffered and already printed
-                         * directly to the console when we received it, and
-                         * record that has level above the console loglevel.
+                         * Skip record if !ignore_loglevel, and
+                         * record has level above the console loglevel.
                          */
                         console_idx = log_next(console_idx);
                         console_seq++;
@@ -2878,16 +2893,20 @@ void wake_up_klogd(void)
         preempt_enable();
 }
 
-int vprintk_deferred(const char *fmt, va_list args)
+void defer_console_output(void)
 {
-        int r;
-
-        r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
-
         preempt_disable();
         __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
         irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
         preempt_enable();
+}
+
+int vprintk_deferred(const char *fmt, va_list args)
+{
+        int r;
+
+        r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+        defer_console_output();
 
         return r;
 }
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index d7d091309054..a0a74c533e4b 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -308,24 +308,33 @@ static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args)
 
 void printk_nmi_enter(void)
 {
-        /*
-         * The size of the extra per-CPU buffer is limited. Use it only when
-         * the main one is locked. If this CPU is not in the safe context,
-         * the lock must be taken on another CPU and we could wait for it.
-         */
-        if ((this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK) &&
-            raw_spin_is_locked(&logbuf_lock)) {
-                this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
-        } else {
-                this_cpu_or(printk_context, PRINTK_NMI_DEFERRED_CONTEXT_MASK);
-        }
+        this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
 }
 
 void printk_nmi_exit(void)
 {
-        this_cpu_and(printk_context,
-                     ~(PRINTK_NMI_CONTEXT_MASK |
-                       PRINTK_NMI_DEFERRED_CONTEXT_MASK));
+        this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK);
+}
+
+/*
+ * Marks a code that might produce many messages in NMI context
+ * and the risk of losing them is more critical than eventual
+ * reordering.
+ *
+ * It has effect only when called in NMI context. Then printk()
+ * will try to store the messages into the main logbuf directly
+ * and use the per-CPU buffers only as a fallback when the lock
+ * is not available.
+ */
+void printk_nmi_direct_enter(void)
+{
+        if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
+                this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK);
+}
+
+void printk_nmi_direct_exit(void)
+{
+        this_cpu_and(printk_context, ~PRINTK_NMI_DIRECT_CONTEXT_MASK);
 }
 
 #else
@@ -363,6 +372,20 @@ void __printk_safe_exit(void)
 
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 {
+        /*
+         * Try to use the main logbuf even in NMI. But avoid calling console
+         * drivers that might have their own locks.
+         */
+        if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
+            raw_spin_trylock(&logbuf_lock)) {
+                int len;
+
+                len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
+                raw_spin_unlock(&logbuf_lock);
+                defer_console_output();
+                return len;
+        }
+
         /* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
         if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
                 return vprintk_nmi(fmt, args);
@@ -371,13 +394,6 @@ __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
         if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
                 return vprintk_safe(fmt, args);
 
-        /*
-         * Use the main logbuf when logbuf_lock is available in NMI.
-         * But avoid calling console drivers that might have their own locks.
-         */
-        if (this_cpu_read(printk_context) & PRINTK_NMI_DEFERRED_CONTEXT_MASK)
-                return vprintk_deferred(fmt, args);
-
         /* No obstacles. */
         return vprintk_default(fmt, args);
 }
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 823687997b01..176debd3481b 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -8288,6 +8288,7 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)
         tracing_off();
 
         local_irq_save(flags);
+        printk_nmi_direct_enter();
 
         /* Simulate the iterator */
         trace_init_global_iter(&iter);
@@ -8367,7 +8368,8 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)
         for_each_tracing_cpu(cpu) {
                 atomic_dec(&per_cpu_ptr(iter.trace_buffer->data, cpu)->disabled);
         }
-        atomic_dec(&dump_running);
+        atomic_dec(&dump_running);
+        printk_nmi_direct_exit();
         local_irq_restore(flags);
 }
 EXPORT_SYMBOL_GPL(ftrace_dump);
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 0b066b3c9284..ce5a45e46885 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -30,6 +30,17 @@ config CONSOLE_LOGLEVEL_DEFAULT
           usage in the kernel. That is controlled by the MESSAGE_LOGLEVEL_DEFAULT
           option.
 
+config CONSOLE_LOGLEVEL_QUIET
+        int "quiet console loglevel (1-15)"
+        range 1 15
+        default "4"
+        help
+          loglevel to use when "quiet" is passed on the kernel commandline.
+
+          When "quiet" is passed on the kernel commandline this loglevel
+          will be used as the loglevel. IOW passing "quiet" will be the
+          equivalent of passing "loglevel=<CONSOLE_LOGLEVEL_QUIET>"
+
 config MESSAGE_LOGLEVEL_DEFAULT
         int "Default message log level (1-7)"
         range 1 7
diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c
index 61a6b5aab07e..15ca78e1c7d4 100644
--- a/lib/nmi_backtrace.c
+++ b/lib/nmi_backtrace.c
@@ -87,11 +87,9 @@ void nmi_trigger_cpumask_backtrace(const cpumask_t *mask,
 
 bool nmi_cpu_backtrace(struct pt_regs *regs)
 {
-        static arch_spinlock_t lock = __ARCH_SPIN_LOCK_UNLOCKED;
         int cpu = smp_processor_id();
 
         if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) {
-                arch_spin_lock(&lock);
                 if (regs && cpu_in_idle(instruction_pointer(regs))) {
                         pr_warn("NMI backtrace for cpu %d skipped: idling at %pS\n",
                                 cpu, (void *)instruction_pointer(regs));
@@ -102,7 +100,6 @@ bool nmi_cpu_backtrace(struct pt_regs *regs)
                         else
                                 dump_stack();
                 }
-                arch_spin_unlock(&lock);
                 cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
                 return true;
         }
diff --git a/lib/test_printf.c b/lib/test_printf.c
index cea592f402ed..53527ea822b5 100644
--- a/lib/test_printf.c
+++ b/lib/test_printf.c
@@ -206,6 +206,7 @@ test_string(void)
 #define PTR_WIDTH 16
 #define PTR ((void *)0xffff0123456789abUL)
 #define PTR_STR "ffff0123456789ab"
+#define PTR_VAL_NO_CRNG "(____ptrval____)"
 #define ZEROS "00000000"        /* hex 32 zero bits */
 
 static int __init
@@ -216,7 +217,16 @@ plain_format(void)
 
         nchars = snprintf(buf, PLAIN_BUF_SIZE, "%p", PTR);
 
-        if (nchars != PTR_WIDTH || strncmp(buf, ZEROS, strlen(ZEROS)) != 0)
+        if (nchars != PTR_WIDTH)
+                return -1;
+
+        if (strncmp(buf, PTR_VAL_NO_CRNG, PTR_WIDTH) == 0) {
+                pr_warn("crng possibly not yet initialized. plain 'p' buffer contains \"%s\"",
+                        PTR_VAL_NO_CRNG);
+                return 0;
+        }
+
+        if (strncmp(buf, ZEROS, strlen(ZEROS)) != 0)
                 return -1;
 
         return 0;
@@ -227,6 +237,7 @@ plain_format(void)
 #define PTR_WIDTH 8
 #define PTR ((void *)0x456789ab)
 #define PTR_STR "456789ab"
+#define PTR_VAL_NO_CRNG "(ptrval)"
 
 static int __init
 plain_format(void)
@@ -245,7 +256,16 @@ plain_hash(void)
 
         nchars = snprintf(buf, PLAIN_BUF_SIZE, "%p", PTR);
 
-        if (nchars != PTR_WIDTH || strncmp(buf, PTR_STR, PTR_WIDTH) == 0)
+        if (nchars != PTR_WIDTH)
+                return -1;
+
+        if (strncmp(buf, PTR_VAL_NO_CRNG, PTR_WIDTH) == 0) {
+                pr_warn("crng possibly not yet initialized. plain 'p' buffer contains \"%s\"",
+                        PTR_VAL_NO_CRNG);
+                return 0;
+        }
+
+        if (strncmp(buf, PTR_STR, PTR_WIDTH) == 0)
                 return -1;
 
         return 0;
diff --git a/lib/vsprintf.c b/lib/vsprintf.c
index a48aaa79d352..cda186230287 100644
--- a/lib/vsprintf.c
+++ b/lib/vsprintf.c
@@ -1942,6 +1942,7 @@ char *pointer(const char *fmt, char *buf, char *end, void *ptr,
                 case 'F':
                         return device_node_string(buf, end, ptr, spec, fmt + 1);
                 }
+                break;
         case 'x':
                 return pointer_string(buf, end, ptr, spec);
         }