Skip to contentSkip to conversation

printk: Fixes and hardening related to KERN_CONT

PATCH Superseded Petr Mladek 4 participants 11 messages Oct 27, 2016 – Oct 31, 2016

Subsystems (4)
Sound Btrfs file system Printk KGDB / KDB /debug_core

v1 of 2 Superseded Latest is v2 →

lore
Share & tools
lore

Petr Mladek

author maintainer
#0 lore raw

cover printk: Fixes and hardening related to KERN_CONT

The first patch fixes a messed output of continuous lines when printing backtraces for all CPUs via NMI. It works well for me.

The other patches fix problems that I noticed when working on the first patch. It would be great if the respective maintainers could do some more testing of them.

Well, it touches several modules. But they are related to one commit so I send them together. Note that the 4th patch depends on the 2nd one.

Petr Mladek (4):
printk/NMI: Handle continuous lines and missing newline printk/kdb: Handle more message headers printk/btrfs: Handle more message headers printk/sound: Handle more message headers

 fs/btrfs/super.c          | 28 +++++++++--------
 include/linux/printk.h    |  8 +++++
 kernel/debug/kdb/kdb_io.c |  2 +-
 kernel/printk/nmi.c       | 78 +++++++++++++++++++++++++++++------------------
 sound/core/misc.c         | 22 +++++++------
 5 files changed, 86 insertions(+), 52 deletions(-)
Signature · 1 line
1.8.5.6
author maintainer
#1 lore raw

PATCH 1/4 printk/NMI: Handle continuous lines and missing newline

The commit 4bcc595ccd80decb4245 ("printk: reinstate KERN_CONT for printing continuation lines") added back KERN_CONT message header. As a result it might appear in the middle of the line when the parts are squashed via the temporary NMI buffer.

A reasonable solution seems to be to split the text in the NNI temporary not only by newlines but also by the message headers.

Another solution would be to filter out KERN_CONT when writing to the temporary buffer. But this would complicate the lockless handling. Also it would not solve problems with a missing newline that was there even before the KERN_CONT stuff.

This patch moves the temporary buffer handling into separate function. I played with it and it seems that using the char pointers make the code easier to read.

Also it moves handling of the s->len overflow into the paranoid check. And allows to recover from the disaster.

Signed-off-by Petr Mladek <[email protected]>
---
 kernel/printk/nmi.c | 78 +++++++++++++++++++++++++++++++++--------------------
 1 file changed, 49 insertions(+), 29 deletions(-)
kernel/printk/nmi.c +49 -29
index 16bab471c7e2..740c90efc65d 100644
@@ -113,16 +113,49 @@ static void printk_nmi_flush_line(const char *text, int len)
 
 }
 
-/*
- * printk one line from the temporary buffer from @start index until
- * and including the @end index.
- */
-static void printk_nmi_flush_seq_line(struct nmi_seq_buf *s,
-					int start, int end)
+/* printk part of the temporary buffer line by line */
+static int printk_nmi_flush_buffer(unsigned char *start, size_t len)
 {
-	const char *buf = s->buffer + start;
+	unsigned char *c, *end;
+	bool header;
+
+	c = start;
+	end = start + len;
+	header = true;
+
+	/* Print line by line. */
+	while (c < end) {
+		if (*c == '\n') {
+			printk_nmi_flush_line(start, c - start + 1);
+			start = ++c;
+			header = true;
+			continue;
+		}
 
-	printk_nmi_flush_line(buf, (end - start) + 1);
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c += 2;
+				continue;
+			}
+
+			printk_nmi_flush_line(start, c - start);
+			start = c++;
+			header = true;
+			continue;
+		}
+
+		header = false;
+		c++;
+	}
+
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		printk_nmi_flush_line(start, end - start);
+		printk_nmi_flush_line("\n", strlen("\n"));
+	}
+
+	return len;
 }
 
 /*

@@ -135,8 +168,8 @@ static void __printk_nmi_flush(struct irq_work *work)
 		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
 	struct nmi_seq_buf *s = container_of(work, struct nmi_seq_buf, work);
 	unsigned long flags;
-	size_t len, size;
-	int i, last_i;
+	size_t len;
+	int i;
 
 	/*
 	 * The lock has two functions. First, one reader has to flush all

@@ -154,35 +187,22 @@ static void __printk_nmi_flush(struct irq_work *work)
 	/*
 	 * This is just a paranoid check that nobody has manipulated
 	 * the buffer an unexpected way. If we printed something then
-	 * @len must only increase.
+	 * @len must only increase. Also it should never overflow the
+	 * buffer size.
 	 */
-	if (i && i >= len) {
+	if ((i && i >= len) || len > sizeof(s->buffer)) {
 		const char *msg = "printk_nmi_flush: internal error\n";
 
 		printk_nmi_flush_line(msg, strlen(msg));
+		len = 0;
 	}
 
 	if (!len)
 		goto out; /* Someone else has already flushed the buffer. */
 
-	/* Make sure that data has been written up to the @len */
+	/* Make sure the data has been written up to the @len */
 	smp_rmb();
-
-	size = min(len, sizeof(s->buffer));
-	last_i = i;
-
-	/* Print line by line. */
-	for (; i < size; i++) {
-		if (s->buffer[i] == '\n') {
-			printk_nmi_flush_seq_line(s, last_i, i);
-			last_i = i + 1;
-		}
-	}
-	/* Check if there was a partial line. */
-	if (last_i < size) {
-		printk_nmi_flush_seq_line(s, last_i, size - 1);
-		printk_nmi_flush_line("\n", strlen("\n"));
-	}
+	i += printk_nmi_flush_buffer(s->buffer + i, len - i);
 
 	/*
 	 * Check that nothing has got added in the meantime and truncate
Signature · 1 line
1.8.5.6
#2 lore raw

Re: [PATCH 1/4] printk/NMI: Handle continuous lines and missing newline

Quoted 5 lines · Petr Mladek

The commit 4bcc595ccd80decb4245 ("printk: reinstate KERN_CONT for printing continuation lines") added back KERN_CONT message header. As a result it might appear in the middle of the line when the parts are squashed via the temporary NMI buffer.

Quoted 7 lines

A reasonable solution seems to be to split the text in the NNI temporary not only by newlines but also by the message headers.

Another solution would be to filter out KERN_CONT when writing to the temporary buffer. But this would complicate the lockless handling. Also it would not solve problems with a missing newline that was there even before the KERN_CONT stuff.

I believe the proper solution there is add the missing EOL/newlines where appropriate. There aren't many treewide. Maybe a couple dozen vs the 250,000 messages with newlines.

Quoted 18 lines

This patch moves the temporary buffer handling into separate function. I played with it and it seems that using the char pointers make the code easier to read.

Also it moves handling of the s->len overflow into the paranoid check. And allows to recover from the disaster.

Signed-off-by Petr Mladek <[email protected]>
---
 kernel/printk/nmi.c | 78 +++++++++++++++++++++++++++++++++--------------------
 1 file changed, 49 insertions(+), 29 deletions(-)
kernel/printk/nmi.c +0 -0
index 16bab471c7e2..740c90efc65d 100644
@@ -113,16 +113,49 @@ static void printk_nmi_flush_line(const char *text, int len)

kernel/printk/nmi.c static void printk_nmi_flush_line(const char *text, int len) · line 117

Quoted 10 lines
kernel/printk/nmi.c +2 -6
 }
 
-/*
- * printk one line from the temporary buffer from @start index until
- * and including the @end index.
- */
-static void printk_nmi_flush_seq_line(struct nmi_seq_buf *s,
-					int start, int end)
+/* printk part of the temporary buffer line by line */
+static int printk_nmi_flush_buffer(unsigned char *start, size_t len)

const unsigned char *?

Quoted 13 lines
kernel/printk/nmi.c +11 -1
 {
-	const char *buf = s->buffer + start;
+	unsigned char *c, *end;
+	bool header;
+
+	c = start;
+	end = start + len;
+	header = true;
+
+	/* Print line by line. */
+	while (c < end) {
+		if (*c == '\n') {
+			printk_nmi_flush_line(start, c - start + 1);

kernel/printk/nmi.c static void printk_nmi_flush_line(const char *text, int len) · line 138

Quoted 10 lines
kernel/printk/nmi.c +8 -1
+			start = ++c;
+			header = true;
+			continue;
+		}
 
-	printk_nmi_flush_line(buf, (end - start) + 1);
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c += 2;

printk_skip_level

Quoted 76 lines
kernel/printk/nmi.c +28 -21
+				continue;
+			}
+
+			printk_nmi_flush_line(start, c - start);
+			start = c++;
+			header = true;
+			continue;
+		}
+
+		header = false;
+		c++;
+	}
+
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		printk_nmi_flush_line(start, end - start);
+		printk_nmi_flush_line("\n", strlen("\n"));
+	}
+
+	return len;
 }
 
 /*

@@ -135,8 +168,8 @@ static void __printk_nmi_flush(struct irq_work *work)
 		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
 	struct nmi_seq_buf *s = container_of(work, struct nmi_seq_buf, work);
 	unsigned long flags;
-	size_t len, size;
-	int i, last_i;
+	size_t len;
+	int i;
 
 	/*
 	 * The lock has two functions. First, one reader has to flush all

@@ -154,35 +187,22 @@ static void __printk_nmi_flush(struct irq_work *work)
 	/*
 	 * This is just a paranoid check that nobody has manipulated
 	 * the buffer an unexpected way. If we printed something then
-	 * @len must only increase.
+	 * @len must only increase. Also it should never overflow the
+	 * buffer size.
 	 */
-	if (i && i >= len) {
+	if ((i && i >= len) || len > sizeof(s->buffer)) {
 		const char *msg = "printk_nmi_flush: internal error\n";
 
 		printk_nmi_flush_line(msg, strlen(msg));
+		len = 0;
 	}
 
 	if (!len)
 		goto out; /* Someone else has already flushed the buffer. */
 
-	/* Make sure that data has been written up to the @len */
+	/* Make sure the data has been written up to the @len */
 	smp_rmb();
-
-	size = min(len, sizeof(s->buffer));
-	last_i = i;
-
-	/* Print line by line. */
-	for (; i < size; i++) {
-		if (s->buffer[i] == '\n') {
-			printk_nmi_flush_seq_line(s, last_i, i);
-			last_i = i + 1;
-		}
-	}
-	/* Check if there was a partial line. */
-	if (last_i < size) {
-		printk_nmi_flush_seq_line(s, last_i, size - 1);
-		printk_nmi_flush_line("\n", strlen("\n"));
-	}
+	i += printk_nmi_flush_buffer(s->buffer + i, len - i);
 
 	/*
 	 * Check that nothing has got added in the meantime and truncate
Reviewed-by
#3 lore raw

Re: [PATCH 1/4] printk/NMI: Handle continuous lines and missing newline

On (10/27/16 09:35), Joe Perches wrote:
[..]

Quoted 7 lines

kernel/printk/nmi.c static void printk_nmi_flush_line(const char *text, int len) · line 138

Quoted 5 lines
kernel/printk/nmi.c +4 -1
-	printk_nmi_flush_line(buf, (end - start) + 1);
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c += 2;

printk_skip_level

agree, printk_skip_level() probably would look better here. other than that, looks good to me. nice that you found it, Petr!

Reviewed-by Sergey Senozhatsky <[email protected]>
	-ss
#4 lore raw

Re: [PATCH 1/4] printk/NMI: Handle continuous lines and missing newline

In reply to Petr Mladek
Quoted 31 lines · Petr Mladek
kernel/printk/nmi.c +27 -2
+static int printk_nmi_flush_buffer(unsigned char *start, size_t len)
 {
-	const char *buf = s->buffer + start;
+	unsigned char *c, *end;
+	bool header;
+
+	c = start;
+	end = start + len;
+	header = true;
+
+	/* Print line by line. */
+	while (c < end) {
+		if (*c == '\n') {
+			printk_nmi_flush_line(start, c - start + 1);
+			start = ++c;
+			header = true;
+			continue;
+		}
 
-	printk_nmi_flush_line(buf, (end - start) + 1);
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c += 2;
+				continue;
+			}
+
+			printk_nmi_flush_line(start, c - start);
+			start = c++;
+			header = true;
+			continue;

kernel/printk/nmi.c static void printk_nmi_flush_line(const char *text, int len) · line 155

Quoted 10 lines
kernel/printk/nmi.c +10 -0
+		}
+
+		header = false;
+		c++;
+	}
+
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		printk_nmi_flush_line(start, end - start);
+		printk_nmi_flush_line("\n", strlen("\n"));

Not introduced by this patch as it was in the original code and the compiler is smart enough to replace strlen("\n") with 1, but still it looks strange.

author maintainer
#5 lore raw

PATCH 2/4 printk/kdb: Handle more message headers

In reply to Petr Mladek

The commit 4bcc595ccd80decb4245096e ("printk: reinstate KERN_CONT for printing continuation lines") allows to define more message headers for a single message. The motivation is that continuous lines might get mixed. Therefore it make sense to define the right log level for every piece of a cont line.

This patch introduces printk_skip_headers() that will skip all headers and uses it in the kdb code instead of printk_skip_level().

This approach helps to fix other printk_skip_level() users independently.

Signed-off-by Petr Mladek <[email protected]>
---
 include/linux/printk.h    | 8 ++++++++
 kernel/debug/kdb/kdb_io.c | 2 +-
 2 files changed, 9 insertions(+), 1 deletion(-)
include/linux/printk.h +8 -0
index 6fdced13d2c9..ebe8918a1f0f 100644
@@ -31,6 +31,14 @@ static inline const char *printk_skip_level(const char *buffer)
 	return buffer;
 }
 
+static inline const char *printk_skip_headers(const char *buffer)
+{
+	while (printk_get_level(buffer))
+		buffer += 2;
+
+	return buffer;
+}
+
 #define PRINTK_POKE_CONSOLE	0x01
 #define PRINTK_POKE_LOGGERS	0x02
kernel/debug/kdb/kdb_io.c +1 -1
index fc1ef736253c..98c9011eac78 100644
@@ -697,7 +697,7 @@ int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap)
 	 * Write to all consoles.
 	 */
 	retlen = strlen(kdb_buffer);
-	cp = (char *) printk_skip_level(kdb_buffer);
+	cp = (char *) printk_skip_headers(kdb_buffer);
 	if (!dbg_kdb_mode && kgdb_connected) {
 		gdbstub_msg_write(cp, retlen - (cp - kdb_buffer));
 	} else {
Signature · 1 line
1.8.5.6
#6 lore raw

Re: [PATCH 2/4] printk/kdb: Handle more message headers

include/linux/printk.h

Quoted 19 lines · Petr Mladek

The commit 4bcc595ccd80decb4245096e ("printk: reinstate KERN_CONT for printing continuation lines") allows to define more message headers for a single message. The motivation is that continuous lines might get mixed. Therefore it make sense to define the right log level for every piece of a cont line.

This patch introduces printk_skip_headers() that will skip all headers and uses it in the kdb code instead of printk_skip_level().

This approach helps to fix other printk_skip_level() users independently.

Signed-off-by Petr Mladek <[email protected]>
---
 include/linux/printk.h    | 8 ++++++++
 kernel/debug/kdb/kdb_io.c | 2 +-
 2 files changed, 9 insertions(+), 1 deletion(-)
include/linux/printk.h +0 -0

[]

include/linux/printk.h static inline const char *printk_skip_level(const char *buffer) · line 37

Quoted 8 lines
include/linux/printk.h +4 -0
@@ -31,6 +31,14 @@ static inline const char *printk_skip_level(const char *buffer)
 	return buffer;
 }
 
+static inline const char *printk_skip_headers(const char *buffer)
+{
+	while (printk_get_level(buffer))
+		buffer += 2;

At some point a level might be more than 1 char and it would be good to keep that check in just one place so using printk_skip_level would be more consistent.

author maintainer
#7 lore raw

PATCH 3/4 printk/btrfs: Handle more message headers

In reply to Petr Mladek

The commit 4bcc595ccd80decb4245096e ("printk: reinstate KERN_CONT for printing continuation lines") allows to define more message headers for a single message. The motivation is that continuous lines might get mixed. Therefore it make sense to define the right log level for every piece of a cont line.

The current btrfs_printk() macros do not support continuous lines at the moment. But better be prepared for a custom messages and avoid potential "lvl" buffer overflow.

This patch iterates over the entire message header. It is interested only into the message level like the original code.

Note that 3 bytes should be enough for the header buffer. I am not sure where the 4 bytes came from. Maybe it expected that both KERN_SOH and the log level strings end with '\0' but they are concatenated.

Also I fixed the default ratelimit level. It looked very strange when it was different from the default log level.

Signed-off-by Petr Mladek <[email protected]>
---
 fs/btrfs/super.c | 28 +++++++++++++++-------------
 1 file changed, 15 insertions(+), 13 deletions(-)
fs/btrfs/super.c +15 -13
index 74ed5aae6cea..2d836c676895 100644
@@ -202,27 +202,29 @@ void __btrfs_handle_fs_error(struct btrfs_fs_info *fs_info, const char *function
 void btrfs_printk(const struct btrfs_fs_info *fs_info, const char *fmt, ...)
 {
 	struct super_block *sb = fs_info->sb;
-	char lvl[4];
+	char lvl[3];
 	struct va_format vaf;
 	va_list args;
-	const char *type = logtypes[4];
+	const char *type = NULL;
 	int kern_level;
 	struct ratelimit_state *ratelimit;
 
 	va_start(args, fmt);
 
-	kern_level = printk_get_level(fmt);
-	if (kern_level) {
-		size_t size = printk_skip_level(fmt) - fmt;
-		memcpy(lvl, fmt,  size);
-		lvl[size] = '\0';
-		fmt += size;
-		type = logtypes[kern_level - '0'];
-		ratelimit = &printk_limits[kern_level - '0'];
-	} else {
+	while ((kern_level = printk_get_level(fmt)) != 0) {
+		if (kern_level >= '0' || kern_level <= '7') {
+			memcpy(lvl, fmt,  2);
+			lvl[2] = '\0';
+			type = logtypes[kern_level - '0'];
+			ratelimit = &printk_limits[kern_level - '0'];
+		}
+		fmt += 2;
+	}
+
+	if (!type) {
 		*lvl = '\0';
-		/* Default to debug output */
-		ratelimit = &printk_limits[7];
+		type = logtypes[4];
+		ratelimit = &printk_limits[4];
 	}
 
 	vaf.fmt = fmt;
Signature · 1 line
1.8.5.6
#8 lore raw

Re: [PATCH 3/4] printk/btrfs: Handle more message headers

Quoted 4 lines · Petr Mladek

Note that 3 bytes should be enough for the header buffer. I am not sure where the 4 bytes came from. Maybe it expected that both KERN_SOH and the log level strings end with '\0' but they are concatenated.

I believe it was from when KERN_<LEVEL> was ascii "<[0-7]>" and not KERN_SOH "[0-7]". I just didn't change the size.

see: commit e2aed8dfa50b ("btrfs: use printk_get_level and printk_skip_level, add __printf, fix fallout")

Acked-by on v1 3/4
#9 lore raw

Re: [PATCH 3/4] printk/btrfs: Handle more message headers

In reply to Petr Mladek
Quoted 9 lines · Petr Mladek

The commit 4bcc595ccd80decb4245096e ("printk: reinstate KERN_CONT for printing continuation lines") allows to define more message headers for a single message. The motivation is that continuous lines might get mixed. Therefore it make sense to define the right log level for every piece of a cont line.

The current btrfs_printk() macros do not support continuous lines at the moment. But better be prepared for a custom messages and avoid potential "lvl" buffer overflow.

I don't think we'll want to support continued lines. The macros just print additional information about the filesystem and the message is supposed to be on one line. If there's multi-line string, the raw printk calls are used (and currently only for debugging purposes).

Acked-by David Sterba <[email protected]>
author maintainer
#10 lore raw

PATCH 4/4 printk/sound: Handle more message headers

In reply to Petr Mladek

The commit 4bcc595ccd80decb4245096e ("printk: reinstate KERN_CONT for printing continuation lines") allows to define more message headers for a single message. The motivation is that continuous lines might get mixed. Therefore it make sense to define the right log level for every piece of a cont line.

This patch tries to copy the entire header. Well, it limits it to 4 bytes because it does not make sense to combine more message headers except for KERN_CONT and some real level.

Signed-off-by Petr Mladek <[email protected]>
---
 sound/core/misc.c | 22 +++++++++++++---------
 1 file changed, 13 insertions(+), 9 deletions(-)
sound/core/misc.c +13 -9
index f2e8226c88fb..52b719cc875d 100644
@@ -68,9 +68,10 @@ void __snd_printk(unsigned int level, const char *path, int line,
 {
 	va_list args;
 #ifdef CONFIG_SND_VERBOSE_PRINTK
-	int kern_level;
 	struct va_format vaf;
-	char verbose_fmt[] = KERN_DEFAULT "ALSA %s:%d %pV";
+	char header[5] = KERN_DEFAULT;
+	const char *end_of_header;
+	size_t size_of_header;
 #endif
 
 #ifdef CONFIG_SND_DEBUG

@@ -83,15 +84,18 @@ void __snd_printk(unsigned int level, const char *path, int line,
 	vaf.fmt = format;
 	vaf.va = &args;
 
-	kern_level = printk_get_level(format);
-	if (kern_level) {
-		const char *end_of_header = printk_skip_level(format);
-		memcpy(verbose_fmt, format, end_of_header - format);
+	end_of_header = printk_skip_headers(format);
+	size_of_header = min((size_t)(end_of_header - format),
+			     sizeof(header) - 1);
+	if (size_of_header) {
+		memcpy(header, format, size_of_header);
+		header[size_of_header] = '\0';
 		vaf.fmt = end_of_header;
-	} else if (level)
-		memcpy(verbose_fmt, KERN_DEBUG, sizeof(KERN_DEBUG) - 1);
-	printk(verbose_fmt, sanity_file_name(path), line, &vaf);
+	} else if (level) {
+		memcpy(header, KERN_DEBUG, sizeof(KERN_DEBUG) - 1);
+	}
 
+	printk("%sALSA %s:%d %pV", header, sanity_file_name(path), line, &vaf);
 #else
 	vprintk(format, args);
 #endif
Signature · 1 line
1.8.5.6