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

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

The other patches fix problems that I noticed when working
on the first patch.

I have incorporated the feedback and did much more testing.
Åll patches have changed so I did not add the taken Reviews
and Acks.

Changes against v1:

  + used const char in printk_nmi_flush_buffer()

  + print the final newline with KERN_CONT in
    printk_nmi_flush_buffer()

  + used printk_skip_level() instead of the hardcoded '2'
    in all patches.

  + define PRINTK_MAX_SINGLE_HEADER_LEN to avoid hardcoding
    the buffer size; it simplified the code in btrfs_printk()

  + ignore KERN_CONT in __snd_printk(); the lines were hard
    to read because of the added stuff like <filename:line>
    for each piece.
    

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          | 26 +++++++++-------
 include/linux/printk.h    | 10 ++++++
 kernel/debug/kdb/kdb_io.c |  2 +-
 kernel/printk/nmi.c       | 78 ++++++++++++++++++++++++++++++-----------------
 sound/core/misc.c         | 20 ++++++++----
 5 files changed, 90 insertions(+), 46 deletions(-)

-- 
1.8.5.6

[PATCH v2 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 prints the final newline as a continuous line.

Finally, 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, 50 insertions(+), 28 deletions(-)

diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index 16bab471c7e2..26cd42d459d3 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -113,16 +113,51 @@ 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(const char *start, size_t len)
 {
-	const char *buf = s->buffer + start;
+	const 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;
+		}
+
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c = printk_skip_level(c);
+				continue;
+			}
+
+			printk_nmi_flush_line(start, c - start);
+			start = c++;
+			header = true;
+			continue;
+		}
+
+		header = false;
+		c++;
+	}
 
-	printk_nmi_flush_line(buf, (end - start) + 1);
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		static const char newline[] = KERN_CONT "\n";
+
+		printk_nmi_flush_line(start, end - start);
+		printk_nmi_flush_line(newline, strlen(newline));
+	}
+
+	return len;
 }
 
 /*
@@ -135,8 +170,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,12 +189,14 @@ 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)
@@ -167,22 +204,7 @@ static void __printk_nmi_flush(struct irq_work *work)
 
 	/* Make sure that 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

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

[Sergey Senozhatsky]

On (11/09/16 13:41), 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.
> 
> 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 prints the final newline as a continuous line.
> 
> Finally, 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>

Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>



without the patch I see prefixes (^Ac) in WARN_ON() output from NMI:

[    0.895911] ------------[ cut here ]------------
[    0.895966] WARNING: CPU: 0 PID: 1 at kernel/[..]
[    0.896026] Modules linked in:^Ac
				^^^^
[..]
[    0.896705] RSP: 0000:ffffc900000176c0 EFLAGS: 00000296^Ac
							^^^^^

	-ss

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

[Steven Rostedt]

On Wed,  9 Nov 2016 13:41:28 +0100
Petr Mladek <pmladek@suse.com> wrote:


>  /*
> @@ -135,8 +170,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,12 +189,14 @@ 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)) {

What's wrong with using s->len? Isn't that what is inside the buffer?
Couldn't just checking against the buffer size print garbage?

-- Steve


>  		const char *msg = "printk_nmi_flush: internal error\n";
>  
>  		printk_nmi_flush_line(msg, strlen(msg));
> +		len = 0;
>  	}
>  
>  	if (!len)
> @@ -167,22 +204,7 @@ static void __printk_nmi_flush(struct irq_work *work)
>  
>  	/* Make sure that 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 v2 1/4] printk/NMI: Handle continuous lines and missing newline

[Petr Mladek]

On Fri 2016-11-11 12:28:51, Steven Rostedt wrote:
> On Wed,  9 Nov 2016 13:41:28 +0100
> Petr Mladek <pmladek@suse.com> wrote:
> 
> 
> >  /*
> > @@ -135,8 +170,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,12 +189,14 @@ 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)) {
> 
> What's wrong with using s->len? Isn't that what is inside the buffer?
> Couldn't just checking against the buffer size print garbage?

Note that this is not the classic seq_buf. It is struct nmi_seq_buf
where "len" is atomic_t and buffer is defined as
buffer[NMI_LOG_BUF_LEN].

It is just a paranoid check that should newer be true if the
implementation is correct. I believe that it makes sense as is.

Best Regards,
Petr

[PATCH v2 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 eac1af8502bb..a0859e169bc3 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 = printk_skip_level(buffer);
+
+	return buffer;
+}
+
 #define CONSOLE_EXT_LOG_MAX	8192
 
 /* printk's without a loglevel use this.. */
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

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

[Steven Rostedt]

On Wed,  9 Nov 2016 13:41:29 +0100
Petr Mladek <pmladek@suse.com> wrote:

> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index eac1af8502bb..a0859e169bc3 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 = printk_skip_level(buffer);

Hmm, shouldn't there be a length passed in here. What happens if buffer
ends with a header. Can't this overflow?

-- Steve

> +
> +	return buffer;
> +}
> +
>  #define CONSOLE_EXT_LOG_MAX	8192
>

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

[Petr Mladek]

On Fri 2016-11-11 12:35:13, Steven Rostedt wrote:
> On Wed,  9 Nov 2016 13:41:29 +0100
> Petr Mladek <pmladek@suse.com> wrote:
> 
> > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > index eac1af8502bb..a0859e169bc3 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 = printk_skip_level(buffer);
> 
> Hmm, shouldn't there be a length passed in here. What happens if buffer
> ends with a header. Can't this overflow?

It is OK when the string has the trailing '\0'. This is the case here.

Note that printk_skip_level() and printk_get_level() would have the
same problem if only the first byte of the header fit the buffer.

Best Regards,
Petr

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

This patch also introduces PRINTK_MAX_SINGLE_HEADER_LEN. Three bytes
are enough for the message level header at the moment. But it used to
be three, see the commit 04d2c8c83d0e3ac5f ("printk: convert the format
for KERN_<LEVEL> to a 2 byte pattern").

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       | 26 +++++++++++++++-----------
 include/linux/printk.h |  2 ++
 2 files changed, 17 insertions(+), 11 deletions(-)

diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
index 74ed5aae6cea..c083d84eaa32 100644
--- a/fs/btrfs/super.c
+++ b/fs/btrfs/super.c
@@ -202,27 +202,31 @@ 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[PRINTK_MAX_SINGLE_HEADER_LEN + 1];
 	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) {
+	while ((kern_level = printk_get_level(fmt)) != 0) {
 		size_t size = printk_skip_level(fmt) - fmt;
-		memcpy(lvl, fmt,  size);
-		lvl[size] = '\0';
+
+		if (kern_level >= '0' || kern_level <= '7') {
+			memcpy(lvl, fmt,  size);
+			lvl[size] = '\0';
+			type = logtypes[kern_level - '0'];
+			ratelimit = &printk_limits[kern_level - '0'];
+		}
 		fmt += size;
-		type = logtypes[kern_level - '0'];
-		ratelimit = &printk_limits[kern_level - '0'];
-	} else {
+	}
+
+	if (!type) {
 		*lvl = '\0';
-		/* Default to debug output */
-		ratelimit = &printk_limits[7];
+		type = logtypes[4];
+		ratelimit = &printk_limits[4];
 	}
 
 	vaf.fmt = fmt;
diff --git a/include/linux/printk.h b/include/linux/printk.h
index a0859e169bc3..afe8ccec1672 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -10,6 +10,8 @@
 extern const char linux_banner[];
 extern const char linux_proc_banner[];
 
+#define PRINTK_MAX_SINGLE_HEADER_LEN 2
+
 static inline int printk_get_level(const char *buffer)
 {
 	if (buffer[0] == KERN_SOH_ASCII && buffer[1]) {
-- 
1.8.5.6

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

[David Sterba]

On Wed, Nov 09, 2016 at 01:41:30PM +0100, 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.
> 
> This patch iterates over the entire message header. It is interested
> only into the message level like the original code.
> 
> This patch also introduces PRINTK_MAX_SINGLE_HEADER_LEN. Three bytes
> are enough for the message level header at the moment. But it used to
> be three, see the commit 04d2c8c83d0e3ac5f ("printk: convert the format
> for KERN_<LEVEL> to a 2 byte pattern").
> 
> 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>

Acked-by: David Sterba <dsterba@suse.com>

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

[Steven Rostedt]

On Wed,  9 Nov 2016 13:41:30 +0100
Petr Mladek <pmladek@suse.com> 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.
> 
> This patch iterates over the entire message header. It is interested
> only into the message level like the original code.
> 
> This patch also introduces PRINTK_MAX_SINGLE_HEADER_LEN. Three bytes
> are enough for the message level header at the moment. But it used to
> be three, see the commit 04d2c8c83d0e3ac5f ("printk: convert the format
> for KERN_<LEVEL> to a 2 byte pattern").
> 
> 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       | 26 +++++++++++++++-----------
>  include/linux/printk.h |  2 ++
>  2 files changed, 17 insertions(+), 11 deletions(-)
> 
> diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
> index 74ed5aae6cea..c083d84eaa32 100644
> --- a/fs/btrfs/super.c
> +++ b/fs/btrfs/super.c
> @@ -202,27 +202,31 @@ 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[PRINTK_MAX_SINGLE_HEADER_LEN + 1];
>  	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) {
> +	while ((kern_level = printk_get_level(fmt)) != 0) {
>  		size_t size = printk_skip_level(fmt) - fmt;
> -		memcpy(lvl, fmt,  size);
> -		lvl[size] = '\0';
> +
> +		if (kern_level >= '0' || kern_level <= '7') {

Shouldn't this be kernel_level >= '0' && kern_level <= '7' ?

-- Steve

> +			memcpy(lvl, fmt,  size);
> +			lvl[size] = '\0';
> +			type = logtypes[kern_level - '0'];
> +			ratelimit = &printk_limits[kern_level - '0'];
> +		}
>  		fmt += size;
> -		type = logtypes[kern_level - '0'];
> -		ratelimit = &printk_limits[kern_level - '0'];
> -	} else {
> +	}
> +
> +	if (!type) {
>  		*lvl = '\0';
> -		/* Default to debug output */
> -		ratelimit = &printk_limits[7];
> +		type = logtypes[4];
> +		ratelimit = &printk_limits[4];
>  	}
>  

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

[Petr Mladek]

On Fri 2016-11-11 12:41:34, Steven Rostedt wrote:
> On Wed,  9 Nov 2016 13:41:30 +0100
> Petr Mladek <pmladek@suse.com> 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.
> > 
> > This patch iterates over the entire message header. It is interested
> > only into the message level like the original code.
> > 
> > This patch also introduces PRINTK_MAX_SINGLE_HEADER_LEN. Three bytes
> > are enough for the message level header at the moment. But it used to
> > be three, see the commit 04d2c8c83d0e3ac5f ("printk: convert the format
> > for KERN_<LEVEL> to a 2 byte pattern").
> > 
> > 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       | 26 +++++++++++++++-----------
> >  include/linux/printk.h |  2 ++
> >  2 files changed, 17 insertions(+), 11 deletions(-)
> > 
> > diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
> > index 74ed5aae6cea..c083d84eaa32 100644
> > --- a/fs/btrfs/super.c
> > +++ b/fs/btrfs/super.c
> > @@ -202,27 +202,31 @@ 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[PRINTK_MAX_SINGLE_HEADER_LEN + 1];
> >  	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) {
> > +	while ((kern_level = printk_get_level(fmt)) != 0) {
> >  		size_t size = printk_skip_level(fmt) - fmt;
> > -		memcpy(lvl, fmt,  size);
> > -		lvl[size] = '\0';
> > +
> > +		if (kern_level >= '0' || kern_level <= '7') {
> 
> Shouldn't this be kernel_level >= '0' && kern_level <= '7' ?

Great catch! I am idiot.

I did all these patches in a hurry before the Plumber conference.
I was blind when checking it later :-(

Thanks a lot for such a careful review.

Best Regards,
Petr

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

[Geert Uytterhoeven]

Hi Petr,

On Wed, Nov 9, 2016 at 1:41 PM, Petr Mladek <pmladek@suse.com> 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.
>
> This patch iterates over the entire message header. It is interested
> only into the message level like the original code.
>
> This patch also introduces PRINTK_MAX_SINGLE_HEADER_LEN. Three bytes
> are enough for the message level header at the moment. But it used to
> be three, see the commit 04d2c8c83d0e3ac5f ("printk: convert the format
> for KERN_<LEVEL> to a 2 byte pattern").
>
> 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       | 26 +++++++++++++++-----------
>  include/linux/printk.h |  2 ++
>  2 files changed, 17 insertions(+), 11 deletions(-)
>
> diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
> index 74ed5aae6cea..c083d84eaa32 100644
> --- a/fs/btrfs/super.c
> +++ b/fs/btrfs/super.c
> @@ -202,27 +202,31 @@ 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[PRINTK_MAX_SINGLE_HEADER_LEN + 1];
>         struct va_format vaf;
>         va_list args;
> -       const char *type = logtypes[4];
> +       const char *type = NULL;
>         int kern_level;
>         struct ratelimit_state *ratelimit;

warning: ‘ratelimit’ may be used uninitialized in this function

So this triggered my attention. It seems my gcc (4.1.2) is not smart enough
to notice that ratelimit will be set to a default value if !type.

Still, IMHO the code is too convoluted for the casual reader.

>         va_start(args, fmt);
>
> -       kern_level = printk_get_level(fmt);
> -       if (kern_level) {
> +       while ((kern_level = printk_get_level(fmt)) != 0) {
>                 size_t size = printk_skip_level(fmt) - fmt;
> -               memcpy(lvl, fmt,  size);
> -               lvl[size] = '\0';
> +
> +               if (kern_level >= '0' || kern_level <= '7') {
> +                       memcpy(lvl, fmt,  size);
> +                       lvl[size] = '\0';
> +                       type = logtypes[kern_level - '0'];
> +                       ratelimit = &printk_limits[kern_level - '0'];
> +               }
>                 fmt += size;
> -               type = logtypes[kern_level - '0'];
> -               ratelimit = &printk_limits[kern_level - '0'];
> -       } else {
> +       }
> +
> +       if (!type) {
>                 *lvl = '\0';
> -               /* Default to debug output */
> -               ratelimit = &printk_limits[7];
> +               type = logtypes[4];
> +               ratelimit = &printk_limits[4];
>         }
>
>         vaf.fmt = fmt;
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index a0859e169bc3..afe8ccec1672 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -10,6 +10,8 @@
>  extern const char linux_banner[];
>  extern const char linux_proc_banner[];
>
> +#define PRINTK_MAX_SINGLE_HEADER_LEN 2

I think you want to use this definition instead of the hardcoded "2" in
printk_skip_level():

| static inline const char *printk_skip_level(const char *buffer)
| {
|         if (printk_get_level(buffer))
|                 return buffer + 2;

return buffer + PRINTK_MAX_SINGLE_HEADER_LEN;

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

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

[Petr Mladek]

On Tue 2016-12-13 10:21:27, Geert Uytterhoeven wrote:
> Hi Petr,
> 
> On Wed, Nov 9, 2016 at 1:41 PM, Petr Mladek <pmladek@suse.com> 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.
> >
> > This patch iterates over the entire message header. It is interested
> > only into the message level like the original code.
> >
> > This patch also introduces PRINTK_MAX_SINGLE_HEADER_LEN. Three bytes
> > are enough for the message level header at the moment. But it used to
> > be three, see the commit 04d2c8c83d0e3ac5f ("printk: convert the format
> > for KERN_<LEVEL> to a 2 byte pattern").
> >
> > 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       | 26 +++++++++++++++-----------
> >  include/linux/printk.h |  2 ++
> >  2 files changed, 17 insertions(+), 11 deletions(-)
> >
> > diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
> > index 74ed5aae6cea..c083d84eaa32 100644
> > --- a/fs/btrfs/super.c
> > +++ b/fs/btrfs/super.c
> > @@ -202,27 +202,31 @@ 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[PRINTK_MAX_SINGLE_HEADER_LEN + 1];
> >         struct va_format vaf;
> >         va_list args;
> > -       const char *type = logtypes[4];
> > +       const char *type = NULL;
> >         int kern_level;
> >         struct ratelimit_state *ratelimit;
> 
> warning: ‘ratelimit’ may be used uninitialized in this function
> 
> So this triggered my attention. It seems my gcc (4.1.2) is not smart enough
> to notice that ratelimit will be set to a default value if !type.
>
> Still, IMHO the code is too convoluted for the casual reader.

I did not see this with gcc 4.8.5. But I agree that it might
be confusing. Please, find a proposed fix below.


> >         vaf.fmt = fmt;
> > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > index a0859e169bc3..afe8ccec1672 100644
> > --- a/include/linux/printk.h
> > +++ b/include/linux/printk.h
> > @@ -10,6 +10,8 @@
> >  extern const char linux_banner[];
> >  extern const char linux_proc_banner[];
> >
> > +#define PRINTK_MAX_SINGLE_HEADER_LEN 2
> 
> I think you want to use this definition instead of the hardcoded "2" in
> printk_skip_level():
> 
> | static inline const char *printk_skip_level(const char *buffer)
> | {
> |         if (printk_get_level(buffer))
> |                 return buffer + 2;
> 
> return buffer + PRINTK_MAX_SINGLE_HEADER_LEN;

I do not like hardcoded constants either. But this is with sync
with the hardcoded buffer[0] and buffer[1] in printk_get_level().

PRINTK_MAX_SINGLE_HEADER_LEN is meant as the maximum length in case
of some non-standard lengths in the future. We used 3-byte headers
in the past. The name is confusing for this use case. I probably
should have avoided _MAX_ in the name. I would leave this for now.
It is well localized...


Here is the proposed fix for the warning:


>From 5b5a8f7ff4f2d5c33316e600a29d45314ac47a16 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Tue, 13 Dec 2016 13:12:56 +0100
Subject: [PATCH] btrfs: Better handle btrfs_printk() defaults
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

The commit 262c5e86fec7cfd ("printk/btrfs: handle more message headers")
triggers:

    warning: ‘ratelimit’ may be used uninitialized in this function

with gcc (4.1.2) and probably many other versions. The code actually
is correct but a bit twisted. Let's make it more straightforward
and set the default values at the beginning.

Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 fs/btrfs/super.c | 12 +++---------
 1 file changed, 3 insertions(+), 9 deletions(-)

diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
index 180f910339f4..3b713b6fcc26 100644
--- a/fs/btrfs/super.c
+++ b/fs/btrfs/super.c
@@ -202,12 +202,12 @@ 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[PRINTK_MAX_SINGLE_HEADER_LEN + 1];
+	char lvl[PRINTK_MAX_SINGLE_HEADER_LEN + 1] = "\0";
 	struct va_format vaf;
 	va_list args;
-	const char *type = NULL;
 	int kern_level;
-	struct ratelimit_state *ratelimit;
+	const char *type = logtypes[4];
+	struct ratelimit_state *ratelimit = &printk_limits[4];
 
 	va_start(args, fmt);
 
@@ -223,12 +223,6 @@ void btrfs_printk(const struct btrfs_fs_info *fs_info, const char *fmt, ...)
 		fmt += size;
 	}
 
-	if (!type) {
-		*lvl = '\0';
-		type = logtypes[4];
-		ratelimit = &printk_limits[4];
-	}
-
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-- 
1.8.5.6

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

[Geert Uytterhoeven]

Hi Petr,

On Tue, Dec 13, 2016 at 2:52 PM, Petr Mladek <pmladek@suse.com> wrote:
> From 5b5a8f7ff4f2d5c33316e600a29d45314ac47a16 Mon Sep 17 00:00:00 2001
> From: Petr Mladek <pmladek@suse.com>
> Date: Tue, 13 Dec 2016 13:12:56 +0100
> Subject: [PATCH] btrfs: Better handle btrfs_printk() defaults
> MIME-Version: 1.0
> Content-Type: text/plain; charset=UTF-8
> Content-Transfer-Encoding: 8bit
>
> The commit 262c5e86fec7cfd ("printk/btrfs: handle more message headers")
> triggers:
>
>     warning: ‘ratelimit’ may be used uninitialized in this function
>
> with gcc (4.1.2) and probably many other versions. The code actually
> is correct but a bit twisted. Let's make it more straightforward
> and set the default values at the beginning.
>
> Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Thanks, that fixes the warning.

Reviewed-by: Geert Uytterhoeven <geert@linux-m68k.org>

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

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

[David Sterba]

On Tue, Dec 13, 2016 at 02:52:47PM +0100, Petr Mladek wrote:
> Here is the proposed fix for the warning:
> 
> 
> From 5b5a8f7ff4f2d5c33316e600a29d45314ac47a16 Mon Sep 17 00:00:00 2001
> From: Petr Mladek <pmladek@suse.com>
> Date: Tue, 13 Dec 2016 13:12:56 +0100
> Subject: [PATCH] btrfs: Better handle btrfs_printk() defaults
> MIME-Version: 1.0
> Content-Type: text/plain; charset=UTF-8
> Content-Transfer-Encoding: 8bit
> 
> The commit 262c5e86fec7cfd ("printk/btrfs: handle more message headers")
> triggers:
> 
>     warning: ‘ratelimit’ may be used uninitialized in this function
> 
> with gcc (4.1.2) and probably many other versions. The code actually
> is correct but a bit twisted. Let's make it more straightforward
> and set the default values at the beginning.
> 
> Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Acked-by: David Sterba <dsterba@suse.com>

[PATCH v2 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 allows to copy only the real message level. We should
ignore KERN_CONT because <filename:line> is added for each message.
By other words, we want to know where each piece of the line comes
from.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 sound/core/misc.c | 20 ++++++++++++++------
 1 file changed, 14 insertions(+), 6 deletions(-)

diff --git a/sound/core/misc.c b/sound/core/misc.c
index f2e8226c88fb..45f03b1d4102 100644
--- a/sound/core/misc.c
+++ b/sound/core/misc.c
@@ -71,6 +71,7 @@ void __snd_printk(unsigned int level, const char *path, int line,
 	int kern_level;
 	struct va_format vaf;
 	char verbose_fmt[] = KERN_DEFAULT "ALSA %s:%d %pV";
+	bool level_found = false;
 #endif
 
 #ifdef CONFIG_SND_DEBUG
@@ -83,15 +84,22 @@ 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);
+	while ((kern_level = printk_get_level(vaf.fmt)) != 0) {
+		const char *end_of_header = printk_skip_level(vaf.fmt);
+
+		/* Ignore KERN_CONT. We print filename:line for each piece. */
+		if (kern_level >= '0' || kern_level <= '7') {
+			memcpy(verbose_fmt, vaf.fmt, end_of_header - vaf.fmt);
+			level_found = true;
+		}
+
 		vaf.fmt = end_of_header;
-	} else if (level)
+	}
+
+	if (!level_found && level)
 		memcpy(verbose_fmt, KERN_DEBUG, sizeof(KERN_DEBUG) - 1);
-	printk(verbose_fmt, sanity_file_name(path), line, &vaf);
 
+	printk(verbose_fmt, sanity_file_name(path), line, &vaf);
 #else
 	vprintk(format, args);
 #endif
-- 
1.8.5.6

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

[Steven Rostedt]

On Wed,  9 Nov 2016 13:41:31 +0100
Petr Mladek <pmladek@suse.com> 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 allows to copy only the real message level. We should
> ignore KERN_CONT because <filename:line> is added for each message.
> By other words, we want to know where each piece of the line comes
> from.
> 
> Signed-off-by: Petr Mladek <pmladek@suse.com>
> ---
>  sound/core/misc.c | 20 ++++++++++++++------
>  1 file changed, 14 insertions(+), 6 deletions(-)
> 
> diff --git a/sound/core/misc.c b/sound/core/misc.c
> index f2e8226c88fb..45f03b1d4102 100644
> --- a/sound/core/misc.c
> +++ b/sound/core/misc.c
> @@ -71,6 +71,7 @@ void __snd_printk(unsigned int level, const char *path, int line,
>  	int kern_level;
>  	struct va_format vaf;
>  	char verbose_fmt[] = KERN_DEFAULT "ALSA %s:%d %pV";
> +	bool level_found = false;
>  #endif
>  
>  #ifdef CONFIG_SND_DEBUG
> @@ -83,15 +84,22 @@ 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);
> +	while ((kern_level = printk_get_level(vaf.fmt)) != 0) {
> +		const char *end_of_header = printk_skip_level(vaf.fmt);
> +
> +		/* Ignore KERN_CONT. We print filename:line for each piece. */
> +		if (kern_level >= '0' || kern_level <= '7') {

Again, the above is always true.

-- Steve

> +			memcpy(verbose_fmt, vaf.fmt, end_of_header - vaf.fmt);
> +			level_found = true;
> +		}
> +
>  		vaf.fmt = end_of_header;
> -	} else if (level)
> +	}
> +
> +	if (!level_found && level)
>  		memcpy(verbose_fmt, KERN_DEBUG, sizeof(KERN_DEBUG) - 1);
> -	printk(verbose_fmt, sanity_file_name(path), line, &vaf);
>  
> +	printk(verbose_fmt, sanity_file_name(path), line, &vaf);
>  #else
>  	vprintk(format, args);
>  #endif