printk: fix purging of old messages

1 files changed, 72 insertions, 58 deletions

diff --git a/printk.patch b/printk.patch
index 45a60bb..6e22b7c 100644
--- a/printk.patch
+++ b/printk.patch
@@ -24,8 +24,8 @@ Subject: [WORK-IN-PROGRESS] printk: introduce structured and multi-facility logg
   thread-safety for multiple printk() invocations for a single line.
 
 - Full-featured syslog facility value support. Different facilities can
-  tag their messages. All userspace-injected messages enforce
-  facility != 0 now, to be able to reliably distinguish them from the
+  tag their messages. All userspace-injected messages enforce a facility
+  value > 0 now, to be able to reliably distinguish them from the
   kernel-generated messages. Independent subsystems like a baseband
   processor or a kernel-related userspace process can use their own
   unique facility values. Multiple independent log streams can co-exist
@@ -98,8 +98,8 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  drivers/base/core.c    |   49 +
  drivers/char/mem.c     |   40 -
  include/linux/printk.h |   13 
- kernel/printk.c        | 1355 +++++++++++++++++++++++++++++++++----------------
- 4 files changed, 988 insertions(+), 469 deletions(-)
+ kernel/printk.c        | 1369 +++++++++++++++++++++++++++++++++----------------
+ 4 files changed, 1002 insertions(+), 469 deletions(-)
 
 --- a/drivers/base/core.c
 +++ b/drivers/base/core.c
@@ -303,7 +303,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
   * If exclusive_console is non-NULL then only this console is to be printed to.
   */
  static struct console *exclusive_console;
-@@ -146,12 +127,521 @@ EXPORT_SYMBOL(console_set_on_cmdline);
+@@ -146,12 +127,525 @@ EXPORT_SYMBOL(console_set_on_cmdline);
  static int console_may_schedule;
  
  #ifdef CONFIG_PRINTK
@@ -419,6 +419,8 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +/* cpu currently holding logbuf_lock */
 +static volatile unsigned int logbuf_cpu = UINT_MAX;
 +
++#define LOG_LINE_MAX 1024
++
 +/* record buffer */
 +#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
  static char __log_buf[__LOG_BUF_LEN];
@@ -468,7 +470,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +	u16 len = log_from_idx(idx)->len;
 +
 +	/* length == 0 indicates the end of the buffer; wrap */
-+	if (len == 0)
++	if (log_from_idx(idx + len)->len == 0)
 +		return 0;
 +	return idx + len;
 +}
@@ -484,34 +486,34 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +	/* number of '\0' padding bytes to next message */
 +	size = sizeof(struct log) + text_len + dict_len;
 +	pad_len = (-size) & (8 - 1);
++	size += pad_len;
 +
-+	if (log_next_idx + size > log_buf_len) {
-+		/*
-+		 * Next message does not fit at the end; wrap. Zero-out
-+		 * the remaining buffer to set len = 0, and leave a clean
-+		 * buffer for things like crash dump.
-+		 */
-+		memset(log_buf + log_next_idx, 0, log_buf_len - log_next_idx);
-+		log_next_idx = 0;
-+	}
-+
-+	/* drop as many old messages as needed */
-+	for (;;) {
++	/* drop old messages until we have enough contiuous space */
++	while (log_first_seq < log_next_seq) {
 +		u32 free;
 +
 +		if (log_next_idx >= log_first_idx)
-+			free = log_buf_len - (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;
-+		free -= log_from_idx(log_next_idx)->len;
 +
-+		if (free >= sizeof(struct log) + text_len + dict_len + pad_len)
++		if (free >= size + sizeof(struct log))
 +			break;
 +
 +		log_first_idx = log_next(log_first_idx);
 +		log_first_seq++;
 +	}
 +
++	if (log_next_idx + size + sizeof(struct log) > log_buf_len) {
++		/*
++		 * This message + empty last message does not fit at the
++		 * end; wrap. Zero-out the remaining buffer to set len = 0,
++		 * and leave a clean buffer for things like crash dump.
++		 */
++		memset(log_buf + log_next_idx, 0, log_buf_len - log_next_idx);
++		log_next_idx = 0;
++	}
++
 +	/* fill message */
 +	msg = log_from_idx(log_next_idx);
 +	memcpy(log_text(msg), text, text_len);
@@ -547,6 +549,8 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +	size_t len = iov_length(iv, count);
 +	ssize_t ret = len;
 +
++	if (len > LOG_LINE_MAX)
++		return -EINVAL;
 +	buf = kmalloc(len+1, GFP_KERNEL);
 +	if (buf == NULL)
 +		return -ENOMEM;
@@ -828,7 +832,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  
  #ifdef CONFIG_KEXEC
  /*
-@@ -165,9 +655,9 @@ static int saved_console_loglevel = -1;
+@@ -165,9 +659,9 @@ static int saved_console_loglevel = -1;
  void log_buf_kexec_setup(void)
  {
  	VMCOREINFO_SYMBOL(log_buf);
@@ -840,7 +844,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  }
  #endif
  
-@@ -191,7 +681,6 @@ early_param("log_buf_len", log_buf_len_s
+@@ -191,7 +685,6 @@ early_param("log_buf_len", log_buf_len_s
  void __init setup_log_buf(int early)
  {
  	unsigned long flags;
@@ -848,7 +852,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	char *new_log_buf;
  	int free;
  
-@@ -219,20 +708,8 @@ void __init setup_log_buf(int early)
+@@ -219,20 +712,8 @@ void __init setup_log_buf(int early)
  	log_buf_len = new_log_buf_len;
  	log_buf = new_log_buf;
  	new_log_buf_len = 0;
@@ -871,7 +875,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
  
  	pr_info("log_buf_len: %d\n", log_buf_len);
-@@ -332,11 +809,160 @@ static int check_syslog_permissions(int
+@@ -332,11 +813,165 @@ static int check_syslog_permissions(int
  	return 0;
  }
  
@@ -928,7 +932,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +	char *text;
 +	int len;
 +
-+	text = kmalloc(1024, GFP_KERNEL);
++	text = kmalloc(LOG_LINE_MAX, GFP_KERNEL);
 +	if (!text)
 +		return -ENOMEM;
 +
@@ -938,7 +942,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +		syslog_seq = log_first_seq;
 +		syslog_idx = log_first_idx;
 +	}
-+	len = syslog_print_line(syslog_idx, text, 1024);
++	len = syslog_print_line(syslog_idx, text, LOG_LINE_MAX);
 +	syslog_idx = log_next(syslog_idx);
 +	syslog_seq++;
 +	raw_spin_unlock_irq(&logbuf_lock);
@@ -955,7 +959,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +	char *text;
 +	int len = 0;
 +
-+	text = kmalloc(1024, GFP_KERNEL);
++	text = kmalloc(LOG_LINE_MAX, GFP_KERNEL);
 +	if (!text)
 +		return -ENOMEM;
 +
@@ -975,14 +979,19 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +		 * Find first record that fits, including all following records,
 +		 * into the user-provided buffer for this dump.
 +		*/
-+		for (idx = clear_idx; idx < log_next_idx; idx = log_next(idx))
++		seq = clear_seq;
++		idx = clear_idx;
++		while (seq < log_next_seq) {
 +			len += syslog_print_line(idx, NULL, 0);
++			idx = log_next(idx);
++			seq++;
++		}
 +		seq = clear_seq;
 +		idx = clear_idx;
-+		while (len > size) {
++		while (len > size && seq < log_next_seq) {
 +			len -= syslog_print_line(idx, NULL, 0);
-+			seq++;
 +			idx = log_next(idx);
++			seq++;
 +		}
 +
 +		/* last message in this dump */
@@ -992,7 +1001,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +		while (len >= 0 && seq < next_seq) {
 +			int textlen;
 +
-+			textlen = syslog_print_line(idx, text, 1024);
++			textlen = syslog_print_line(idx, text, LOG_LINE_MAX);
 +			if (textlen < 0) {
 +				len = textlen;
 +				break;
@@ -1035,7 +1044,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	int error;
  
  	error = check_syslog_permissions(type, from_file);
-@@ -364,28 +990,14 @@ int do_syslog(int type, char __user *buf
+@@ -364,28 +999,14 @@ int do_syslog(int type, char __user *buf
  			goto out;
  		}
  		error = wait_event_interruptible(log_wait,
@@ -1067,7 +1076,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  		/* FALL THRU */
  	/* Read last kernel messages */
  	case SYSLOG_ACTION_READ_ALL:
-@@ -399,52 +1011,11 @@ int do_syslog(int type, char __user *buf
+@@ -399,52 +1020,11 @@ int do_syslog(int type, char __user *buf
  			error = -EFAULT;
  			goto out;
  		}
@@ -1122,7 +1131,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	/* Disable logging to console */
  	case SYSLOG_ACTION_CONSOLE_OFF:
  		if (saved_console_loglevel == -1)
-@@ -472,7 +1043,28 @@ int do_syslog(int type, char __user *buf
+@@ -472,7 +1052,33 @@ int do_syslog(int type, char __user *buf
  		break;
  	/* Number of chars in the log buffer */
  	case SYSLOG_ACTION_SIZE_UNREAD:
@@ -1141,18 +1150,23 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +			 */
 +			error = log_next_idx - syslog_idx;
 +		} else {
++			u64 seq;
 +			u32 idx;
 +
 +			error = 0;
-+			for (idx = syslog_idx; idx < log_next_idx;
-+			     idx = log_next(idx))
++			seq = syslog_seq;
++			idx = syslog_idx;
++			while (seq < log_next_seq) {
 +				error += syslog_print_line(idx, NULL, 0);
++				idx = log_next(idx);
++				seq++;
++			}
 +		}
 +		raw_spin_unlock_irq(&logbuf_lock);
  		break;
  	/* Size of the log buffer */
  	case SYSLOG_ACTION_SIZE_BUFFER:
-@@ -501,29 +1093,11 @@ void kdb_syslog_data(char *syslog_data[4
+@@ -501,29 +1107,11 @@ void kdb_syslog_data(char *syslog_data[4
  {
  	syslog_data[0] = log_buf;
  	syslog_data[1] = log_buf + log_buf_len;
@@ -1184,7 +1198,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  static bool __read_mostly ignore_loglevel;
  
  static int __init ignore_loglevel_setup(char *str)
-@@ -540,142 +1114,33 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
+@@ -540,142 +1128,33 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
  	"print all kernel messages to the console.");
  
  /*
@@ -1346,7 +1360,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  }
  
  /*
-@@ -700,16 +1165,6 @@ static void zap_locks(void)
+@@ -700,16 +1179,6 @@ static void zap_locks(void)
  	sema_init(&console_sem, 1);
  }
  
@@ -1363,7 +1377,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  /* Check if we have any console registered that can be called early in boot. */
  static int have_callable_console(void)
  {
-@@ -722,51 +1177,6 @@ static int have_callable_console(void)
+@@ -722,51 +1191,6 @@ static int have_callable_console(void)
  	return 0;
  }
  
@@ -1415,7 +1429,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  /*
   * Can we actually use the console at this time on this cpu?
   *
-@@ -810,17 +1220,12 @@ static int console_trylock_for_printk(un
+@@ -810,17 +1234,12 @@ static int console_trylock_for_printk(un
  			retval = 0;
  		}
  	}
@@ -1434,7 +1448,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  
  int printk_delay_msec __read_mostly;
  
-@@ -836,15 +1241,22 @@ static inline void printk_delay(void)
+@@ -836,15 +1255,22 @@ static inline void printk_delay(void)
  	}
  }
  
@@ -1447,10 +1461,10 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
 +			    const char *fmt, va_list args)
 +{
 +	static int recursion_bug;
-+	static char buf[1024];
++	static char buf[LOG_LINE_MAX];
 +	static size_t buflen;
 +	static int buflevel;
-+	static char textbuf[1024];
++	static char textbuf[LOG_LINE_MAX];
 +	char *text = textbuf;
 +	size_t textlen;
  	unsigned long flags;
@@ -1464,7 +1478,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  
  	boot_delay_msec();
  	printk_delay();
-@@ -856,7 +1268,7 @@ asmlinkage int vprintk(const char *fmt,
+@@ -856,7 +1282,7 @@ asmlinkage int vprintk(const char *fmt,
  	/*
  	 * Ouch, printk recursed into itself!
  	 */
@@ -1473,7 +1487,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  		/*
  		 * If a crash is occurring during printk() on this CPU,
  		 * then try to get the crash message out but make sure
-@@ -873,97 +1285,92 @@ asmlinkage int vprintk(const char *fmt,
+@@ -873,97 +1299,92 @@ asmlinkage int vprintk(const char *fmt,
  
  	lockdep_off();
  	raw_spin_lock(&logbuf_lock);
@@ -1642,7 +1656,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	 */
  	if (console_trylock_for_printk(this_cpu))
  		console_unlock();
-@@ -974,12 +1381,73 @@ out_restore_irqs:
+@@ -974,12 +1395,73 @@ out_restore_irqs:
  
  	return printed_len;
  }
@@ -1718,7 +1732,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  {
  }
  
-@@ -1217,7 +1685,7 @@ int is_console_locked(void)
+@@ -1217,7 +1699,7 @@ int is_console_locked(void)
  }
  
  /*
@@ -1727,7 +1741,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
   */
  #define PRINTK_BUF_SIZE		512
  
-@@ -1253,6 +1721,10 @@ void wake_up_klogd(void)
+@@ -1253,6 +1735,10 @@ void wake_up_klogd(void)
  		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
  }
  
@@ -1738,7 +1752,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  /**
   * console_unlock - unlock the console system
   *
-@@ -1263,15 +1735,16 @@ void wake_up_klogd(void)
+@@ -1263,15 +1749,16 @@ void wake_up_klogd(void)
   * by printk().  If this is the case, console_unlock(); emits
   * the output prior to releasing the lock.
   *
@@ -1758,14 +1772,14 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  
  	if (console_suspended) {
  		up(&console_sem);
-@@ -1281,17 +1754,40 @@ void console_unlock(void)
+@@ -1281,17 +1768,40 @@ void console_unlock(void)
  	console_may_schedule = 0;
  
  again:
 -	for ( ; ; ) {
 +	for (;;) {
 +		struct log *msg;
-+		static char text[1024];
++		static char text[LOG_LINE_MAX];
 +		size_t len;
 +		int level;
 +
@@ -1807,7 +1821,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  		start_critical_timings();
  		local_irq_restore(flags);
  	}
-@@ -1312,8 +1808,7 @@ again:
+@@ -1312,8 +1822,7 @@ again:
  	 * flush, no worries.
  	 */
  	raw_spin_lock(&logbuf_lock);
@@ -1817,7 +1831,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
  
  	if (retry && console_trylock())
-@@ -1549,7 +2044,8 @@ void register_console(struct console *ne
+@@ -1549,7 +2058,8 @@ void register_console(struct console *ne
  		 * for us.
  		 */
  		raw_spin_lock_irqsave(&logbuf_lock, flags);
@@ -1827,7 +1841,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
  		/*
  		 * We're about to replay the log buffer.  Only do this to the
-@@ -1758,6 +2254,9 @@ int kmsg_dump_unregister(struct kmsg_dum
+@@ -1758,6 +2268,9 @@ int kmsg_dump_unregister(struct kmsg_dum
  }
  EXPORT_SYMBOL_GPL(kmsg_dump_unregister);
  
@@ -1837,7 +1851,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  /**
   * kmsg_dump - dump kernel log to kernel message dumpers.
   * @reason: the reason (oops, panic etc) for dumping
-@@ -1767,8 +2266,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_unregister);
+@@ -1767,8 +2280,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_unregister);
   */
  void kmsg_dump(enum kmsg_dump_reason reason)
  {
@@ -1847,7 +1861,7 @@ Signed-off-by: Kay Sievers <kay@vrfy.org>
  	struct kmsg_dumper *dumper;
  	const char *s1, *s2;
  	unsigned long l1, l2;
-@@ -1780,24 +2278,27 @@ void kmsg_dump(enum kmsg_dump_reason rea
+@@ -1780,24 +2292,27 @@ void kmsg_dump(enum kmsg_dump_reason rea
  	/* Theoretically, the log could move on after we do this, but
  	   there's not a lot we can do about that. The new messages
  	   will overwrite the start of what we dump. */