1 files changed, 227 insertions, 121 deletions

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a45b50962295..ea2d5f6962ed 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -54,20 +54,16 @@
 #include "console_cmdline.h"
 #include "braille.h"
 
-/* printk's without a loglevel use this.. */
-#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL
-
-/* We show everything that is MORE important than this.. */
-#define MINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */
-#define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */
-
 int console_printk[4] = {
-        DEFAULT_CONSOLE_LOGLEVEL,       /* console_loglevel */
+        CONSOLE_LOGLEVEL_DEFAULT,       /* console_loglevel */
         DEFAULT_MESSAGE_LOGLEVEL,       /* default_message_loglevel */
-        MINIMUM_CONSOLE_LOGLEVEL,       /* minimum_console_loglevel */
-        DEFAULT_CONSOLE_LOGLEVEL,       /* default_console_loglevel */
+        CONSOLE_LOGLEVEL_MIN,           /* minimum_console_loglevel */
+        CONSOLE_LOGLEVEL_DEFAULT,       /* default_console_loglevel */
 };
 
+/* Deferred messaged from sched code are marked by this special level */
+#define SCHED_MESSAGE_LOGLEVEL -2
+
 /*
  * Low level drivers may need that to know if they can schedule in
  * their unblank() callback or not. So let's export it.
@@ -91,6 +87,29 @@ static struct lockdep_map console_lock_dep_map = {
 #endif
 
 /*
+ * Helper macros to handle lockdep when locking/unlocking console_sem. We use
+ * macros instead of functions so that _RET_IP_ contains useful information.
+ */
+#define down_console_sem() do { \
+        down(&console_sem);\
+        mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);\
+} while (0)
+
+static int __down_trylock_console_sem(unsigned long ip)
+{
+        if (down_trylock(&console_sem))
+                return 1;
+        mutex_acquire(&console_lock_dep_map, 0, 1, ip);
+        return 0;
+}
+#define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_)
+
+#define up_console_sem() do { \
+        mutex_release(&console_lock_dep_map, 1, _RET_IP_);\
+        up(&console_sem);\
+} while (0)
+
+/*
  * This is used for debugging the mess that is the VT code by
  * keeping track if we have the console semaphore held. It's
  * definitely not the perfect debug tool (we don't know if _WE_
@@ -206,8 +225,9 @@ struct printk_log {
 };
 
 /*
- * The logbuf_lock protects kmsg buffer, indices, counters. It is also
- * used in interesting ways to provide interlocking in console_unlock();
+ * The logbuf_lock protects kmsg buffer, indices, counters.  This can be taken
+ * within the scheduler's rq lock. It must be released before calling
+ * console_unlock() or anything else that might wake up a process.
  */
 static DEFINE_RAW_SPINLOCK(logbuf_lock);
 
@@ -250,9 +270,6 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
-/* cpu currently holding logbuf_lock */
-static volatile unsigned int logbuf_cpu = UINT_MAX;
-
 /* human readable text of the record */
 static char *log_text(const struct printk_log *msg)
 {
@@ -297,34 +314,106 @@ static u32 log_next(u32 idx)
         return idx + msg->len;
 }
 
-/* insert record into the buffer, discard old ones, update heads */
-static void log_store(int facility, int level,
-                      enum log_flags flags, u64 ts_nsec,
-                      const char *dict, u16 dict_len,
-                      const char *text, u16 text_len)
+/*
+ * Check whether there is enough free space for the given message.
+ *
+ * The same values of first_idx and next_idx mean that the buffer
+ * is either empty or full.
+ *
+ * If the buffer is empty, we must respect the position of the indexes.
+ * They cannot be reset to the beginning of the buffer.
+ */
+static int logbuf_has_space(u32 msg_size, bool empty)
 {
-        struct printk_log *msg;
-        u32 size, pad_len;
+        u32 free;
 
-        /* number of '\0' padding bytes to next message */
-        size = sizeof(struct printk_log) + text_len + dict_len;
-        pad_len = (-size) & (LOG_ALIGN - 1);
-        size += pad_len;
+        if (log_next_idx > log_first_idx || empty)
+                free = max(log_buf_len - log_next_idx, log_first_idx);
+        else
+                free = log_first_idx - log_next_idx;
+
+        /*
+         * We need space also for an empty header that signalizes wrapping
+         * of the buffer.
+         */
+        return free >= msg_size + sizeof(struct printk_log);
+}
 
+static int log_make_free_space(u32 msg_size)
+{
         while (log_first_seq < log_next_seq) {
-                u32 free;
+                if (logbuf_has_space(msg_size, false))
+                        return 0;
+                /* drop old messages until we have enough continuous space */
+                log_first_idx = log_next(log_first_idx);
+                log_first_seq++;
+        }
 
-                if (log_next_idx > log_first_idx)
-                        free = max(log_buf_len - log_next_idx, log_first_idx);
-                else
-                        free = log_first_idx - log_next_idx;
+        /* sequence numbers are equal, so the log buffer is empty */
+        if (logbuf_has_space(msg_size, true))
+                return 0;
 
-                if (free >= size + sizeof(struct printk_log))
-                        break;
+        return -ENOMEM;
+}
 
-                /* drop old messages until we have enough contiuous space */
-                log_first_idx = log_next(log_first_idx);
-                log_first_seq++;
+/* compute the message size including the padding bytes */
+static u32 msg_used_size(u16 text_len, u16 dict_len, u32 *pad_len)
+{
+        u32 size;
+
+        size = sizeof(struct printk_log) + text_len + dict_len;
+        *pad_len = (-size) & (LOG_ALIGN - 1);
+        size += *pad_len;
+
+        return size;
+}
+
+/*
+ * Define how much of the log buffer we could take at maximum. The value
+ * must be greater than two. Note that only half of the buffer is available
+ * when the index points to the middle.
+ */
+#define MAX_LOG_TAKE_PART 4
+static const char trunc_msg[] = "<truncated>";
+
+static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
+                        u16 *dict_len, u32 *pad_len)
+{
+        /*
+         * The message should not take the whole buffer. Otherwise, it might
+         * get removed too soon.
+         */
+        u32 max_text_len = log_buf_len / MAX_LOG_TAKE_PART;
+        if (*text_len > max_text_len)
+                *text_len = max_text_len;
+        /* enable the warning message */
+        *trunc_msg_len = strlen(trunc_msg);
+        /* disable the "dict" completely */
+        *dict_len = 0;
+        /* compute the size again, count also the warning message */
+        return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
+}
+
+/* insert record into the buffer, discard old ones, update heads */
+static int log_store(int facility, int level,
+                     enum log_flags flags, u64 ts_nsec,
+                     const char *dict, u16 dict_len,
+                     const char *text, u16 text_len)
+{
+        struct printk_log *msg;
+        u32 size, pad_len;
+        u16 trunc_msg_len = 0;
+
+        /* number of '\0' padding bytes to next message */
+        size = msg_used_size(text_len, dict_len, &pad_len);
+
+        if (log_make_free_space(size)) {
+                /* truncate the message if it is too long for empty buffer */
+                size = truncate_msg(&text_len, &trunc_msg_len,
+                                    &dict_len, &pad_len);
+                /* survive when the log buffer is too small for trunc_msg */
+                if (log_make_free_space(size))
+                        return 0;
         }
 
         if (log_next_idx + size + sizeof(struct printk_log) > log_buf_len) {
@@ -341,6 +430,10 @@ static void log_store(int facility, int level,
         msg = (struct printk_log *)(log_buf + log_next_idx);
         memcpy(log_text(msg), text, text_len);
         msg->text_len = text_len;
+        if (trunc_msg_len) {
+                memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
+                msg->text_len += trunc_msg_len;
+        }
         memcpy(log_dict(msg), dict, dict_len);
         msg->dict_len = dict_len;
         msg->facility = facility;
@@ -356,6 +449,8 @@ static void log_store(int facility, int level,
         /* insert message */
         log_next_idx += msg->len;
         log_next_seq++;
+
+        return msg->text_len;
 }
 
 #ifdef CONFIG_SECURITY_DMESG_RESTRICT
@@ -1303,7 +1398,10 @@ static void zap_locks(void)
         sema_init(&console_sem, 1);
 }
 
-/* Check if we have any console registered that can be called early in boot. */
+/*
+ * Check if we have any console that is capable of printing while cpu is
+ * booting or shutting down. Requires console_sem.
+ */
 static int have_callable_console(void)
 {
         struct console *con;
@@ -1318,10 +1416,9 @@ static int have_callable_console(void)
 /*
  * Can we actually use the console at this time on this cpu?
  *
- * Console drivers may assume that per-cpu resources have
- * been allocated. So unless they're explicitly marked as
- * being able to cope (CON_ANYTIME) don't call them until
- * this CPU is officially up.
+ * Console drivers may assume that per-cpu resources have been allocated. So
+ * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
+ * call them until this CPU is officially up.
  */
 static inline int can_use_console(unsigned int cpu)
 {
@@ -1333,36 +1430,24 @@ static inline int can_use_console(unsigned int cpu)
  * messages from a 'printk'. Return true (and with the
  * console_lock held, and 'console_locked' set) if it
  * is successful, false otherwise.
- *
- * This gets called with the 'logbuf_lock' spinlock held and
- * interrupts disabled. It should return with 'lockbuf_lock'
- * released but interrupts still disabled.
  */
-static int console_trylock_for_printk(unsigned int cpu)
-        __releases(&logbuf_lock)
+static int console_trylock_for_printk(void)
 {
-        int retval = 0, wake = 0;
+        unsigned int cpu = smp_processor_id();
 
-        if (console_trylock()) {
-                retval = 1;
-
-                /*
-                 * If we can't use the console, we need to release
-                 * the console semaphore by hand to avoid flushing
-                 * the buffer. We need to hold the console semaphore
-                 * in order to do this test safely.
-                 */
-                if (!can_use_console(cpu)) {
-                        console_locked = 0;
-                        wake = 1;
-                        retval = 0;
-                }
+        if (!console_trylock())
+                return 0;
+        /*
+         * If we can't use the console, we need to release the console
+         * semaphore by hand to avoid flushing the buffer. We need to hold the
+         * console semaphore in order to do this test safely.
+         */
+        if (!can_use_console(cpu)) {
+                console_locked = 0;
+                up_console_sem();
+                return 0;
         }
-        logbuf_cpu = UINT_MAX;
-        raw_spin_unlock(&logbuf_lock);
-        if (wake)
-                up(&console_sem);
-        return retval;
+        return 1;
 }
 
 int printk_delay_msec __read_mostly;
@@ -1490,11 +1575,19 @@ asmlinkage int vprintk_emit(int facility, int level,
         static int recursion_bug;
         static char textbuf[LOG_LINE_MAX];
         char *text = textbuf;
-        size_t text_len;
+        size_t text_len = 0;
         enum log_flags lflags = 0;
         unsigned long flags;
         int this_cpu;
         int printed_len = 0;
+        bool in_sched = false;
+        /* cpu currently holding logbuf_lock in this function */
+        static volatile unsigned int logbuf_cpu = UINT_MAX;
+
+        if (level == SCHED_MESSAGE_LOGLEVEL) {
+                level = -1;
+                in_sched = true;
+        }
 
         boot_delay_msec(level);
         printk_delay();
@@ -1516,7 +1609,8 @@ asmlinkage int vprintk_emit(int facility, int level,
                  */
                 if (!oops_in_progress && !lockdep_recursing(current)) {
                         recursion_bug = 1;
-                        goto out_restore_irqs;
+                        local_irq_restore(flags);
+                        return 0;
                 }
                 zap_locks();
         }
@@ -1530,17 +1624,22 @@ asmlinkage int vprintk_emit(int facility, int level,
                         "BUG: recent printk recursion!";
 
                 recursion_bug = 0;
-                printed_len += strlen(recursion_msg);
+                text_len = strlen(recursion_msg);
                 /* emit KERN_CRIT message */
-                log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-                          NULL, 0, recursion_msg, printed_len);
+                printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
+                                         NULL, 0, recursion_msg, text_len);
         }
 
         /*
          * The printf needs to come first; we need the syslog
          * prefix which might be passed-in as a parameter.
          */
-        text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+        if (in_sched)
+                text_len = scnprintf(text, sizeof(textbuf),
+                                     KERN_WARNING "[sched_delayed] ");
+
+        text_len += vscnprintf(text + text_len,
+                               sizeof(textbuf) - text_len, fmt, args);
 
         /* mark and strip a trailing newline */
         if (text_len && text[text_len-1] == '\n') {
@@ -1586,9 +1685,12 @@ asmlinkage int vprintk_emit(int facility, int level,
                         cont_flush(LOG_NEWLINE);
 
                 /* buffer line if possible, otherwise store it right away */
-                if (!cont_add(facility, level, text, text_len))
-                        log_store(facility, level, lflags | LOG_CONT, 0,
-                                  dict, dictlen, text, text_len);
+                if (cont_add(facility, level, text, text_len))
+                        printed_len += text_len;
+                else
+                        printed_len += log_store(facility, level,
+                                                 lflags | LOG_CONT, 0,
+                                                 dict, dictlen, text, text_len);
         } else {
                 bool stored = false;
 
@@ -1607,26 +1709,35 @@ asmlinkage int vprintk_emit(int facility, int level,
                         cont_flush(LOG_NEWLINE);
                 }
 
-                if (!stored)
-                        log_store(facility, level, lflags, 0,
-                                  dict, dictlen, text, text_len);
+                if (stored)
+                        printed_len += text_len;
+                else
+                        printed_len += log_store(facility, level, lflags, 0,
+                                                 dict, dictlen, text, text_len);
         }
-        printed_len += text_len;
+
+        logbuf_cpu = UINT_MAX;
+        raw_spin_unlock(&logbuf_lock);
+        lockdep_on();
+        local_irq_restore(flags);
+
+        /* If called from the scheduler, we can not call up(). */
+        if (in_sched)
+                return printed_len;
 
         /*
+         * Disable preemption to avoid being preempted while holding
+         * console_sem which would prevent anyone from printing to console
+         */
+        preempt_disable();
+        /*
          * Try to acquire and then immediately release the console semaphore.
          * The release will print out buffers and wake up /dev/kmsg and syslog()
          * users.
-         *
-         * The console_trylock_for_printk() function will release 'logbuf_lock'
-         * regardless of whether it actually gets the console semaphore or not.
          */
-        if (console_trylock_for_printk(this_cpu))
+        if (console_trylock_for_printk())
                 console_unlock();
-
-        lockdep_on();
-out_restore_irqs:
-        local_irq_restore(flags);
+        preempt_enable();
 
         return printed_len;
 }
@@ -1674,7 +1785,7 @@ EXPORT_SYMBOL(printk_emit);
  *
  * See the vsnprintf() documentation for format string extensions over C99.
  */
-asmlinkage int printk(const char *fmt, ...)
+asmlinkage __visible int printk(const char *fmt, ...)
 {
         va_list args;
         int r;
@@ -1737,7 +1848,7 @@ void early_vprintk(const char *fmt, va_list ap)
         }
 }
 
-asmlinkage void early_printk(const char *fmt, ...)
+asmlinkage __visible void early_printk(const char *fmt, ...)
 {
         va_list ap;
 
@@ -1882,16 +1993,14 @@ void suspend_console(void)
         printk("Suspending console(s) (use no_console_suspend to debug)\n");
         console_lock();
         console_suspended = 1;
-        up(&console_sem);
-        mutex_release(&console_lock_dep_map, 1, _RET_IP_);
+        up_console_sem();
 }
 
 void resume_console(void)
 {
         if (!console_suspend_enabled)
                 return;
-        down(&console_sem);
-        mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
+        down_console_sem();
         console_suspended = 0;
         console_unlock();
 }
@@ -1933,12 +2042,11 @@ void console_lock(void)
 {
         might_sleep();
 
-        down(&console_sem);
+        down_console_sem();
         if (console_suspended)
                 return;
         console_locked = 1;
         console_may_schedule = 1;
-        mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
 }
 EXPORT_SYMBOL(console_lock);
 
@@ -1952,15 +2060,14 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
-        if (down_trylock(&console_sem))
+        if (down_trylock_console_sem())
                 return 0;
         if (console_suspended) {
-                up(&console_sem);
+                up_console_sem();
                 return 0;
         }
         console_locked = 1;
         console_may_schedule = 0;
-        mutex_acquire(&console_lock_dep_map, 0, 1, _RET_IP_);
         return 1;
 }
 EXPORT_SYMBOL(console_trylock);
@@ -2022,7 +2129,7 @@ void console_unlock(void)
         bool retry;
 
         if (console_suspended) {
-                up(&console_sem);
+                up_console_sem();
                 return;
         }
 
@@ -2043,10 +2150,15 @@ again:
                 }
 
                 if (console_seq < log_first_seq) {
+                        len = sprintf(text, "** %u printk messages dropped ** ",
+                                      (unsigned)(log_first_seq - console_seq));
+
                         /* messages are gone, move to first one */
                         console_seq = log_first_seq;
                         console_idx = log_first_idx;
                         console_prev = 0;
+                } else {
+                        len = 0;
                 }
 skip:
                 if (console_seq == log_next_seq)
@@ -2071,8 +2183,8 @@ skip:
                 }
 
                 level = msg->level;
-                len = msg_print_text(msg, console_prev, false,
-                                     text, sizeof(text));
+                len += msg_print_text(msg, console_prev, false,
+                                      text + len, sizeof(text) - len);
                 console_idx = log_next(console_idx);
                 console_seq++;
                 console_prev = msg->flags;
@@ -2084,7 +2196,6 @@ skip:
                 local_irq_restore(flags);
         }
         console_locked = 0;
-        mutex_release(&console_lock_dep_map, 1, _RET_IP_);
 
         /* Release the exclusive_console once it is used */
         if (unlikely(exclusive_console))
@@ -2092,7 +2203,7 @@ skip:
 
         raw_spin_unlock(&logbuf_lock);
 
-        up(&console_sem);
+        up_console_sem();
 
         /*
          * Someone could have filled up the buffer again, so re-check if there's
@@ -2137,7 +2248,7 @@ void console_unblank(void)
          * oops_in_progress is set to 1..
          */
         if (oops_in_progress) {
-                if (down_trylock(&console_sem) != 0)
+                if (down_trylock_console_sem() != 0)
                         return;
         } else
                 console_lock();
@@ -2413,6 +2524,7 @@ int unregister_console(struct console *console)
         if (console_drivers != NULL && console->flags & CON_CONSDEV)
                 console_drivers->flags |= CON_CONSDEV;
 
+        console->flags &= ~CON_ENABLED;
         console_unlock();
         console_sysfs_notify();
         return res;
@@ -2437,21 +2549,19 @@ late_initcall(printk_late_init);
 /*
  * Delayed printk version, for scheduler-internal messages:
  */
-#define PRINTK_BUF_SIZE         512
-
 #define PRINTK_PENDING_WAKEUP   0x01
-#define PRINTK_PENDING_SCHED    0x02
+#define PRINTK_PENDING_OUTPUT   0x02
 
 static DEFINE_PER_CPU(int, printk_pending);
-static DEFINE_PER_CPU(char [PRINTK_BUF_SIZE], printk_sched_buf);
 
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
         int pending = __this_cpu_xchg(printk_pending, 0);
 
-        if (pending & PRINTK_PENDING_SCHED) {
-                char *buf = __get_cpu_var(printk_sched_buf);
-                pr_warn("[sched_delayed] %s", buf);
+        if (pending & PRINTK_PENDING_OUTPUT) {
+                /* If trylock fails, someone else is doing the printing */
+                if (console_trylock())
+                        console_unlock();
         }
 
         if (pending & PRINTK_PENDING_WAKEUP)
@@ -2473,23 +2583,19 @@ void wake_up_klogd(void)
         preempt_enable();
 }
 
-int printk_sched(const char *fmt, ...)
+int printk_deferred(const char *fmt, ...)
 {
-        unsigned long flags;
         va_list args;
-        char *buf;
         int r;
 
-        local_irq_save(flags);
-        buf = __get_cpu_var(printk_sched_buf);
-
+        preempt_disable();
         va_start(args, fmt);
-        r = vsnprintf(buf, PRINTK_BUF_SIZE, fmt, args);
+        r = vprintk_emit(0, SCHED_MESSAGE_LOGLEVEL, NULL, 0, fmt, args);
         va_end(args);
 
-        __this_cpu_or(printk_pending, PRINTK_PENDING_SCHED);
+        __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
         irq_work_queue(&__get_cpu_var(wake_up_klogd_work));
-        local_irq_restore(flags);
+        preempt_enable();
 
         return r;
 }