[PATCH 0/4] printk: Fixes and hardening related to KERN_CONT

[PATCH 0/4] printk: Fixes and hardening related to KERN_CONT

[Petr Mladek]

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(-)

-- 
1.8.5.6

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

[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.

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 <pmladek@suse.com>
---
 kernel/printk/nmi.c | 78 +++++++++++++++++++++++++++++++++--------------------
 1 file changed, 49 insertions(+), 29 deletions(-)

diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index 16bab471c7e2..740c90efc65d 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -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
-- 
1.8.5.6

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

[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 <pmladek@suse.com>
---
 include/linux/printk.h    | 8 ++++++++
 kernel/debug/kdb/kdb_io.c | 2 +-
 2 files changed, 9 insertions(+), 1 deletion(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 6fdced13d2c9..ebe8918a1f0f 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -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
 
diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c
index fc1ef736253c..98c9011eac78 100644
--- a/kernel/debug/kdb/kdb_io.c
+++ b/kernel/debug/kdb/kdb_io.c
@@ -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 {
-- 
1.8.5.6

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

[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 <pmladek@suse.com>
---
 fs/btrfs/super.c | 28 +++++++++++++++-------------
 1 file changed, 15 insertions(+), 13 deletions(-)

diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
index 74ed5aae6cea..2d836c676895 100644
--- a/fs/btrfs/super.c
+++ b/fs/btrfs/super.c
@@ -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;
-- 
1.8.5.6

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

[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 <pmladek@suse.com>
---
 sound/core/misc.c | 22 +++++++++++++---------
 1 file changed, 13 insertions(+), 9 deletions(-)

diff --git a/sound/core/misc.c b/sound/core/misc.c
index f2e8226c88fb..52b719cc875d 100644
--- a/sound/core/misc.c
+++ b/sound/core/misc.c
@@ -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
-- 
1.8.5.6

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

[Joe Perches]

On Thu, 2016-10-27 at 17:52 +0200, Petr Mladek wrote:
> 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")

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

[Joe Perches]

On Thu, 2016-10-27 at 17:52 +0200, Petr Mladek wrote:
> 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.

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.

> 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 <pmladek@suse.com>
> ---
>  kernel/printk/nmi.c | 78 +++++++++++++++++++++++++++++++++--------------------
>  1 file changed, 49 insertions(+), 29 deletions(-)
> 
> diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
> index 16bab471c7e2..740c90efc65d 100644
> --- a/kernel/printk/nmi.c
> +++ b/kernel/printk/nmi.c
> @@ -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 unsigned char *?

>  {
> -	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;

printk_skip_level

> +				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

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

[Joe Perches]

On Thu, 2016-10-27 at 17:52 +0200, Petr Mladek wrote:
> 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 <pmladek@suse.com>
> ---
>  include/linux/printk.h    | 8 ++++++++
>  kernel/debug/kdb/kdb_io.c | 2 +-
>  2 files changed, 9 insertions(+), 1 deletion(-)
> 
> diff --git a/include/linux/printk.h b/include/linux/printk.h
[]
> @@ -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.

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

[Sergey Senozhatsky]

On (10/27/16 09:35), Joe Perches wrote:
[..]
> > -	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 <sergey.senozhatsky@gmail.com>

	-ss

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

[David Sterba]

On Thu, Oct 27, 2016 at 05:52:51PM +0200, Petr Mladek wrote:
> +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"));

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.

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

[David Sterba]

On Thu, Oct 27, 2016 at 05:52:53PM +0200, Petr Mladek wrote:
> 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 <dsterba@suse.com>