Merge branch 'printk-cleanups'
authorLinus Torvalds <torvalds@linux-foundation.org>
Mon, 10 Oct 2016 16:29:50 +0000 (09:29 -0700)
committerLinus Torvalds <torvalds@linux-foundation.org>
Mon, 10 Oct 2016 16:29:50 +0000 (09:29 -0700)
Merge my system logging cleanups, triggered by the broken '\n' patches.

The line continuation handling has been broken basically forever, and
the code to handle the system log records was both confusing and
dubious.  And it would do entirely the wrong thing unless you always had
a terminating newline, partly because it couldn't actually see whether a
message was marked KERN_CONT or not (but partly because the LOG_CONT
handling in the recording code was rather confusing too).

This re-introduces a real semantically meaningful KERN_CONT, and fixes
the few places I noticed where it was missing.  There are probably more
missing cases, since KERN_CONT hasn't actually had any semantic meaning
for at least four years (other than the checkpatch meaning of "no log
level necessary, this is a continuation line").

This also allows the combination of KERN_CONT and a log level.  In that
case the log level will be ignored if the merging with a previous line
is successful, but if a new record is needed, that new record will now
get the right log level.

That also means that you can at least in theory combine KERN_CONT with
the "pr_info()" style helpers, although any use of pr_fmt() prefixing
would make that just result in a mess, of course (the prefix would end
up in the middle of a continuing line).

* printk-cleanups:
  printk: make reading the kernel log flush pending lines
  printk: re-organize log_output() to be more legible
  printk: split out core logging code into helper function
  printk: reinstate KERN_CONT for printing continuation lines

1  2 
drivers/tty/vt/vt.c
kernel/printk/printk.c
security/selinux/ss/policydb.c

diff --combined drivers/tty/vt/vt.c
@@@ -1312,12 -1312,12 +1312,12 @@@ static int vc_t416_color(struct vc_dat
        if (i > vc->vc_npar)
                return i;
  
 -      if (vc->vc_par[i] == 5 && i < vc->vc_npar) {
 -              /* 256 colours -- ubiquitous */
 +      if (vc->vc_par[i] == 5 && i + 1 <= vc->vc_npar) {
 +              /* 256 colours */
                i++;
                rgb_from_256(vc->vc_par[i], &c);
 -      } else if (vc->vc_par[i] == 2 && i <= vc->vc_npar + 3) {
 -              /* 24 bit -- extremely rare */
 +      } else if (vc->vc_par[i] == 2 && i + 3 <= vc->vc_npar) {
 +              /* 24 bit */
                c.r = vc->vc_par[i + 1];
                c.g = vc->vc_par[i + 2];
                c.b = vc->vc_par[i + 3];
@@@ -1415,11 -1415,6 +1415,11 @@@ static void csi_m(struct vc_data *vc
                                (vc->vc_color & 0x0f);
                        break;
                default:
 +                      if (vc->vc_par[i] >= 90 && vc->vc_par[i] <= 107) {
 +                              if (vc->vc_par[i] < 100)
 +                                      vc->vc_intensity = 2;
 +                              vc->vc_par[i] -= 60;
 +                      }
                        if (vc->vc_par[i] >= 30 && vc->vc_par[i] <= 37)
                                vc->vc_color = color_table[vc->vc_par[i] - 30]
                                        | (vc->vc_color & 0xf0);
@@@ -3187,11 -3182,11 +3187,11 @@@ static int do_bind_con_driver(const str
  
        pr_info("Console: switching ");
        if (!deflt)
-               printk("consoles %d-%d ", first+1, last+1);
+               printk(KERN_CONT "consoles %d-%d ", first+1, last+1);
        if (j >= 0) {
                struct vc_data *vc = vc_cons[j].d;
  
-               printk("to %s %s %dx%d\n",
+               printk(KERN_CONT "to %s %s %dx%d\n",
                       vc->vc_can_do_color ? "colour" : "mono",
                       desc, vc->vc_cols, vc->vc_rows);
  
                        update_screen(vc);
                }
        } else
-               printk("to %s\n", desc);
+               printk(KERN_CONT "to %s\n", desc);
  
        retval = 0;
  err:
diff --combined kernel/printk/printk.c
@@@ -253,17 -253,6 +253,17 @@@ static int preferred_console = -1
  int console_set_on_cmdline;
  EXPORT_SYMBOL(console_set_on_cmdline);
  
 +#ifdef CONFIG_OF
 +static bool of_specified_console;
 +
 +void console_set_by_of(void)
 +{
 +      of_specified_console = true;
 +}
 +#else
 +# define of_specified_console false
 +#endif
 +
  /* Flag: console code may call schedule() */
  static int console_may_schedule;
  
@@@ -666,11 -655,8 +666,8 @@@ static ssize_t msg_print_ext_header(cha
         * better readable output. 'c' in the record flags mark the first
         * fragment of a line, '+' the following.
         */
-       if (msg->flags & LOG_CONT && !(prev_flags & LOG_CONT))
-               cont = 'c';
-       else if ((msg->flags & LOG_CONT) ||
-                ((prev_flags & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
-               cont = '+';
+       if (msg->flags & LOG_CONT)
+               cont = (prev_flags & LOG_CONT) ? '+' : 'c';
  
        return scnprintf(buf, size, "%u,%llu,%llu,%c;",
                       (msg->facility << 3) | msg->level, seq, ts_usec, cont);
@@@ -797,6 -783,8 +794,8 @@@ static ssize_t devkmsg_write(struct kio
        return ret;
  }
  
+ static void cont_flush(void);
  static ssize_t devkmsg_read(struct file *file, char __user *buf,
                            size_t count, loff_t *ppos)
  {
        if (ret)
                return ret;
        raw_spin_lock_irq(&logbuf_lock);
+       cont_flush();
        while (user->seq == log_next_seq) {
                if (file->f_flags & O_NONBLOCK) {
                        ret = -EAGAIN;
@@@ -874,6 -863,7 +874,7 @@@ static loff_t devkmsg_llseek(struct fil
                return -ESPIPE;
  
        raw_spin_lock_irq(&logbuf_lock);
+       cont_flush();
        switch (whence) {
        case SEEK_SET:
                /* the first record */
@@@ -912,6 -902,7 +913,7 @@@ static unsigned int devkmsg_poll(struc
        poll_wait(file, &log_wait, wait);
  
        raw_spin_lock_irq(&logbuf_lock);
+       cont_flush();
        if (user->seq < log_next_seq) {
                /* return error when data has vanished underneath us */
                if (user->seq < log_first_seq)
@@@ -1298,6 -1289,7 +1300,7 @@@ static int syslog_print(char __user *bu
                size_t skip;
  
                raw_spin_lock_irq(&logbuf_lock);
+               cont_flush();
                if (syslog_seq < log_first_seq) {
                        /* messages are gone, move to first one */
                        syslog_seq = log_first_seq;
@@@ -1357,6 -1349,7 +1360,7 @@@ static int syslog_print_all(char __use
                return -ENOMEM;
  
        raw_spin_lock_irq(&logbuf_lock);
+       cont_flush();
        if (buf) {
                u64 next_seq;
                u64 seq;
@@@ -1518,6 -1511,7 +1522,7 @@@ int do_syslog(int type, char __user *bu
        /* Number of chars in the log buffer */
        case SYSLOG_ACTION_SIZE_UNREAD:
                raw_spin_lock_irq(&logbuf_lock);
+               cont_flush();
                if (syslog_seq < log_first_seq) {
                        /* messages are gone, move to first one */
                        syslog_seq = log_first_seq;
@@@ -1654,35 -1648,33 +1659,33 @@@ static struct cont 
        bool flushed:1;                 /* buffer sealed and committed */
  } cont;
  
- static void cont_flush(enum log_flags flags)
+ static void cont_flush(void)
  {
        if (cont.flushed)
                return;
        if (cont.len == 0)
                return;
        if (cont.cons) {
                /*
                 * If a fragment of this line was directly flushed to the
                 * console; wait for the console to pick up the rest of the
                 * line. LOG_NOCONS suppresses a duplicated output.
                 */
-               log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+               log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS,
                          cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-               cont.flags = flags;
                cont.flushed = true;
        } else {
                /*
                 * If no fragment of this line ever reached the console,
                 * just submit it to the store and free the buffer.
                 */
-               log_store(cont.facility, cont.level, flags, 0,
+               log_store(cont.facility, cont.level, cont.flags, 0,
                          NULL, 0, cont.buf, cont.len);
                cont.len = 0;
        }
  }
  
- static bool cont_add(int facility, int level, const char *text, size_t len)
+ static bool cont_add(int facility, int level, enum log_flags flags, const char *text, size_t len)
  {
        if (cont.len && cont.flushed)
                return false;
         * the line gets too long, split it up in separate records.
         */
        if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
-               cont_flush(LOG_CONT);
+               cont_flush();
                return false;
        }
  
                cont.level = level;
                cont.owner = current;
                cont.ts_nsec = local_clock();
-               cont.flags = 0;
+               cont.flags = flags;
                cont.cons = 0;
                cont.flushed = false;
        }
        memcpy(cont.buf + cont.len, text, len);
        cont.len += len;
  
+       // The original flags come from the first line,
+       // but later continuations can add a newline.
+       if (flags & LOG_NEWLINE) {
+               cont.flags |= LOG_NEWLINE;
+               cont_flush();
+       }
        if (cont.len > (sizeof(cont.buf) * 80) / 100)
-               cont_flush(LOG_CONT);
+               cont_flush();
  
        return true;
  }
@@@ -1744,6 -1743,31 +1754,31 @@@ static size_t cont_print_text(char *tex
        return textlen;
  }
  
+ static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len)
+ {
+       /*
+        * If an earlier line was buffered, and we're a continuation
+        * write from the same process, try to add it to the buffer.
+        */
+       if (cont.len) {
+               if (cont.owner == current && (lflags & LOG_CONT)) {
+                       if (cont_add(facility, level, lflags, text, text_len))
+                               return text_len;
+               }
+               /* Otherwise, make sure it's flushed */
+               cont_flush();
+       }
+       /* If it doesn't end in a newline, try to buffer the current line */
+       if (!(lflags & LOG_NEWLINE)) {
+               if (cont_add(facility, level, lflags, text, text_len))
+                       return text_len;
+       }
+       /* Store it in the record log */
+       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)
  
        /* strip kernel syslog prefix and extract log level or control flags */
        if (facility == 0) {
-               int kern_level = printk_get_level(text);
+               int kern_level;
  
-               if (kern_level) {
-                       const char *end_of_header = printk_skip_level(text);
+               while ((kern_level = printk_get_level(text)) != 0) {
                        switch (kern_level) {
                        case '0' ... '7':
                                if (level == LOGLEVEL_DEFAULT)
                                /* fallthrough */
                        case 'd':       /* KERN_DEFAULT */
                                lflags |= LOG_PREFIX;
+                               break;
+                       case 'c':       /* KERN_CONT */
+                               lflags |= LOG_CONT;
                        }
-                       /*
-                        * No need to check length here because vscnprintf
-                        * put '\0' at the end of the string. Only valid and
-                        * newly printed level is detected.
-                        */
-                       text_len -= end_of_header - text;
-                       text = (char *)end_of_header;
+                       text_len -= 2;
+                       text += 2;
                }
        }
  
        if (dict)
                lflags |= LOG_PREFIX|LOG_NEWLINE;
  
-       if (!(lflags & LOG_NEWLINE)) {
-               /*
-                * Flush the conflicting buffer. An earlier newline was missing,
-                * or another task also prints continuation lines.
-                */
-               if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
-                       cont_flush(LOG_NEWLINE);
-               /* buffer line if possible, otherwise store it right away */
-               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;
-               /*
-                * If an earlier newline was missing and it was the same task,
-                * either merge it with the current buffer and flush, or if
-                * there was a race with interrupts (prefix == true) then just
-                * flush it out and store this line separately.
-                * If the preceding printk was from a different task and missed
-                * a newline, flush and append the newline.
-                */
-               if (cont.len) {
-                       if (cont.owner == current && !(lflags & LOG_PREFIX))
-                               stored = cont_add(facility, level, text,
-                                                 text_len);
-                       cont_flush(LOG_NEWLINE);
-               }
-               if (stored)
-                       printed_len += text_len;
-               else
-                       printed_len += log_store(facility, level, lflags, 0,
-                                                dict, dictlen, text, text_len);
-       }
+       printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
  
        logbuf_cpu = UINT_MAX;
        raw_spin_unlock(&logbuf_lock);
@@@ -2658,7 -2642,7 +2653,7 @@@ void register_console(struct console *n
         *      didn't select a console we take the first one
         *      that registers here.
         */
 -      if (preferred_console < 0) {
 +      if (preferred_console < 0 && !of_specified_console) {
                if (newcon->index < 0)
                        newcon->index = 0;
                if (newcon->setup == NULL ||
@@@ -3040,6 -3024,7 +3035,7 @@@ void kmsg_dump(enum kmsg_dump_reason re
                dumper->active = true;
  
                raw_spin_lock_irqsave(&logbuf_lock, flags);
+               cont_flush();
                dumper->cur_seq = clear_seq;
                dumper->cur_idx = clear_idx;
                dumper->next_seq = log_next_seq;
@@@ -3130,6 -3115,7 +3126,7 @@@ bool kmsg_dump_get_line(struct kmsg_dum
        bool ret;
  
        raw_spin_lock_irqsave(&logbuf_lock, flags);
+       cont_flush();
        ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
        raw_spin_unlock_irqrestore(&logbuf_lock, flags);
  
@@@ -3172,6 -3158,7 +3169,7 @@@ bool kmsg_dump_get_buffer(struct kmsg_d
                goto out;
  
        raw_spin_lock_irqsave(&logbuf_lock, flags);
+       cont_flush();
        if (dumper->cur_seq < log_first_seq) {
                /* messages are gone, move to first available one */
                dumper->cur_seq = log_first_seq;
@@@ -527,9 -527,9 +527,9 @@@ static int policydb_index(struct policy
        printk(KERN_DEBUG "SELinux:  %d users, %d roles, %d types, %d bools",
               p->p_users.nprim, p->p_roles.nprim, p->p_types.nprim, p->p_bools.nprim);
        if (p->mls_enabled)
-               printk(", %d sens, %d cats", p->p_levels.nprim,
+               printk(KERN_CONT ", %d sens, %d cats", p->p_levels.nprim,
                       p->p_cats.nprim);
-       printk("\n");
+       printk(KERN_CONT "\n");
  
        printk(KERN_DEBUG "SELinux:  %d classes, %d rules\n",
               p->p_classes.nprim, p->te_avtab.nel);
  
        rc = -ENOMEM;
        p->class_val_to_struct =
 -              kmalloc(p->p_classes.nprim * sizeof(*(p->class_val_to_struct)),
 +              kzalloc(p->p_classes.nprim * sizeof(*(p->class_val_to_struct)),
                        GFP_KERNEL);
        if (!p->class_val_to_struct)
                goto out;
  
        rc = -ENOMEM;
        p->role_val_to_struct =
 -              kmalloc(p->p_roles.nprim * sizeof(*(p->role_val_to_struct)),
 +              kzalloc(p->p_roles.nprim * sizeof(*(p->role_val_to_struct)),
                        GFP_KERNEL);
        if (!p->role_val_to_struct)
                goto out;
  
        rc = -ENOMEM;
        p->user_val_to_struct =
 -              kmalloc(p->p_users.nprim * sizeof(*(p->user_val_to_struct)),
 +              kzalloc(p->p_users.nprim * sizeof(*(p->user_val_to_struct)),
                        GFP_KERNEL);
        if (!p->user_val_to_struct)
                goto out;
@@@ -964,7 -964,7 +964,7 @@@ int policydb_context_isvalid(struct pol
                 * Role must be authorized for the type.
                 */
                role = p->role_val_to_struct[c->role - 1];
 -              if (!ebitmap_get_bit(&role->types, c->type - 1))
 +              if (!role || !ebitmap_get_bit(&role->types, c->type - 1))
                        /* role may not be associated with type */
                        return 0;
  
@@@ -1094,9 -1094,6 +1094,9 @@@ static int str_read(char **strp, gfp_t 
        int rc;
        char *str;
  
 +      if ((len == 0) || (len == (u32)-1))
 +              return -EINVAL;
 +
        str = kmalloc(len + 1, flags);
        if (!str)
                return -ENOMEM;
@@@ -2417,7 -2414,6 +2417,7 @@@ int policydb_read(struct policydb *p, v
                } else
                        tr->tclass = p->process_class;
  
 +              rc = -EINVAL;
                if (!policydb_role_isvalid(p, tr->role) ||
                    !policydb_type_isvalid(p, tr->type) ||
                    !policydb_class_isvalid(p, tr->tclass) ||