[PATCH] printk: Do not lose last line in kmsg dump

[PATCH] printk: Do not lose last line in kmsg dump

[Vincent Whitchurch]

kmsg_dump_get_buffer() is supposed to select the youngest log messages
which fit into the provided buffer.  When that function determines the
correct start index, by looping and calling msg_print_text() with a NULL
buffer, msg_print_text() calculates a length which would allow the
youngest log messages to completely fill the provided buffer.

However, when doing the actual printing, an off-by-one error in
msg_print_text() leads to that function allowing the provided buffer to
only be filled to (size - 1).

So if the lengths of the selected youngest log messages happen to
precisely fill up the provided buffer, the last log message is not
included.

For example, with the following two final prints:

[    6.427502] AAAAAAAAAAAAA
[    6.427769] BBBBBBBB12345

A dump of a 64-byte buffer filled by kmsg_dump_get_buffer(), before this
patch:

 00000000: 3c 30 3e 5b 20 20 20 20 36 2e 35 32 32 31 39 37  <0>[    6.522197
 00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
 00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
 00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................

After this patch:

 00000000: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 35 30 32  <0>[    6.427502
 00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
 00000020: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 37 36 39  <0>[    6.427769
 00000030: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.

Note that this bug only affects the kmsg dump code.  msg_print_text() is
also used from the syslog code and console_unlock() but this bug does
trigger there since the buffers used there are never filled up
completely (since they are only used to print individual lines, and
their size is always LOG_LINE_MAX + PREFIX_MAX, and PREFIX_MAX has a
value which is larger than the largest possible prefix).

Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
---
I posted this patch two years ago and received no replies.  This problem is
still present in mainline.  https://lore.kernel.org/patchwork/patch/781106/

 kernel/printk/printk.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1888f6a3b694..7679d779d5cc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1318,7 +1318,7 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog,
 		}
 
 		if (buf) {
-			if (prefix_len + text_len + 1 >= size - len)
+			if (prefix_len + text_len + 1 > size - len)
 				break;
 
 			memcpy(buf + len, prefix, prefix_len);
-- 
2.20.0

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Sergey Senozhatsky]

On (07/09/19 10:10), Vincent Whitchurch wrote:
> A dump of a 64-byte buffer filled by kmsg_dump_get_buffer(), before this
> patch:
> 
>  00000000: 3c 30 3e 5b 20 20 20 20 36 2e 35 32 32 31 39 37  <0>[    6.522197
>  00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
>  00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
>  00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
> 
> After this patch:
> 
>  00000000: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 35 30 32  <0>[    6.427502
>  00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
>  00000020: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 37 36 39  <0>[    6.427769
>  00000030: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.

[..]

> @@ -1318,7 +1318,7 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog,
>  		}
>  
>  		if (buf) {
> -			if (prefix_len + text_len + 1 >= size - len)
> +			if (prefix_len + text_len + 1 > size - len)
>  				break;

So with this patch the last byte of the buffer is 0xA. It's a bit
uncomfortable that `len', which we return from msg_print_text(),
now points one byte beyond the buffer:

	buf[len++] = '\n';
	return len;

This is not very common. Not sure what usually happens to kmsg_dump
buffers, but anyone who'd do a rather innocent

	kmsg_dump(buf, &len);
	buf[len] = 0x00;

will write to something which is not a kmsg buffer (in some cases).

	-ss

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Petr Mladek]

On Tue 2019-07-09 19:12:30, Sergey Senozhatsky wrote:
> On (07/09/19 10:10), Vincent Whitchurch wrote:
> > A dump of a 64-byte buffer filled by kmsg_dump_get_buffer(), before this
> > patch:
> > 
> >  00000000: 3c 30 3e 5b 20 20 20 20 36 2e 35 32 32 31 39 37  <0>[    6.522197
> >  00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
> >  00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
> >  00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
> > 
> > After this patch:
> > 
> >  00000000: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 35 30 32  <0>[    6.427502
> >  00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
> >  00000020: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 37 36 39  <0>[    6.427769
> >  00000030: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
> 
> [..]
> 
> > @@ -1318,7 +1318,7 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog,
> >  		}
> >  
> >  		if (buf) {
> > -			if (prefix_len + text_len + 1 >= size - len)
> > +			if (prefix_len + text_len + 1 > size - len)
> >  				break;
> 
> So with this patch the last byte of the buffer is 0xA. It's a bit
> uncomfortable that `len', which we return from msg_print_text(),
> now points one byte beyond the buffer:
> 
> 	buf[len++] = '\n';
> 	return len;
> 
> This is not very common. Not sure what usually happens to kmsg_dump
> buffers, but anyone who'd do a rather innocent
> 
> 	kmsg_dump(buf, &len);
> 	buf[len] = 0x00;
> 
> will write to something which is not a kmsg buffer (in some cases).

I have the same worries.

On the other hand. The function does not store the trailing '\0'
into the buffer itself. The callers would need to add it themself.
It is their responsibility to avoid a buffer overflow.

I have checked several users and it seems that nobody adds or
needs the trailing '\0'.

It is ugly to do not use the entire buffer just because theoretical
buggy users. It is only one byte. But it might be more bytes if
each function in the call chain gives up one byte from the same reason.

With some fear I give it:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Anyway, if nobody vetoes the patch, I would schedule it for 5.4.
We are already in the merge window and it deserves some testing
in linux-next.

Best Regards,
Petr

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Steven Rostedt]

On Tue, 9 Jul 2019 16:29:39 +0200
Petr Mladek <pmladek@suse.com> wrote:

> Anyway, if nobody vetoes the patch, I would schedule it for 5.4.
> We are already in the merge window and it deserves some testing
> in linux-next.

+1

-- Steve

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Vincent Whitchurch]

On Tue, Jul 09, 2019 at 04:29:39PM +0200, Petr Mladek wrote:
> On Tue 2019-07-09 19:12:30, Sergey Senozhatsky wrote:
> > On (07/09/19 10:10), Vincent Whitchurch wrote:
> > > A dump of a 64-byte buffer filled by kmsg_dump_get_buffer(), before this
> > > patch:
> > > 
> > >  00000000: 3c 30 3e 5b 20 20 20 20 36 2e 35 32 32 31 39 37  <0>[    6.522197
> > >  00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
> > >  00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
> > >  00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
> > > 
> > > After this patch:
> > > 
> > >  00000000: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 35 30 32  <0>[    6.427502
> > >  00000010: 5d 20 41 41 41 41 41 41 41 41 41 41 41 41 41 0a  ] AAAAAAAAAAAAA.
> > >  00000020: 3c 30 3e 5b 20 20 20 20 36 2e 34 32 37 37 36 39  <0>[    6.427769
> > >  00000030: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
> > 
> > [..]
> > 
> > > @@ -1318,7 +1318,7 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog,
> > >  		}
> > >  
> > >  		if (buf) {
> > > -			if (prefix_len + text_len + 1 >= size - len)
> > > +			if (prefix_len + text_len + 1 > size - len)
> > >  				break;
> > 
> > So with this patch the last byte of the buffer is 0xA. It's a bit
> > uncomfortable that `len', which we return from msg_print_text(),
> > now points one byte beyond the buffer:
> > 
> > 	buf[len++] = '\n';
> > 	return len;
> > 
> > This is not very common. Not sure what usually happens to kmsg_dump
> > buffers, but anyone who'd do a rather innocent
> > 
> > 	kmsg_dump(buf, &len);
> > 	buf[len] = 0x00;
> > 
> > will write to something which is not a kmsg buffer (in some cases).
> 
> I have the same worries.
> 
> On the other hand. The function does not store the trailing '\0'
> into the buffer itself. The callers would need to add it themself.
> It is their responsibility to avoid a buffer overflow.
> 
> I have checked several users and it seems that nobody adds or
> needs the trailing '\0'.
> 
> It is ugly to do not use the entire buffer just because theoretical
> buggy users.

All the callers of kmsg_dump_get_buffer() seem to be fine but these two
users of kmsg_dump_get_line(), which also calls msg_print_text(), have
exactly the code which you and Sergey worry about:

arch/powerpc/xmon/xmon.c
2836:	while (kmsg_dump_get_line_nolock(&dumper, false, buf, sizeof(buf), &len)) {
2837-		buf[len] = '\0';

arch/um/kernel/kmsg_dump.c
29:	while (kmsg_dump_get_line(dumper, true, line, sizeof(line), &len)) {
30-		line[len] = '\0';

I guess we should fix these first and leave this patch as is?

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Sergey Senozhatsky]

On (07/10/19 10:04), Vincent Whitchurch wrote:
> > > [..]
> > > 
> > > > @@ -1318,7 +1318,7 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog,
> > > >  		}
> > > >  
> > > >  		if (buf) {
> > > > -			if (prefix_len + text_len + 1 >= size - len)
> > > > +			if (prefix_len + text_len + 1 > size - len)
> > > >  				break;
> > > 
> > > So with this patch the last byte of the buffer is 0xA. It's a bit
> > > uncomfortable that `len', which we return from msg_print_text(),
> > > now points one byte beyond the buffer:
> > > 
> > > 	buf[len++] = '\n';
> > > 	return len;
> > > 
> > > This is not very common. Not sure what usually happens to kmsg_dump
> > > buffers, but anyone who'd do a rather innocent
> > > 
> > > 	kmsg_dump(buf, &len);
> > > 	buf[len] = 0x00;
> > > 
> > > will write to something which is not a kmsg buffer (in some cases).

[..]

> arch/powerpc/xmon/xmon.c
> 2836:	while (kmsg_dump_get_line_nolock(&dumper, false, buf, sizeof(buf), &len)) {
> 2837-		buf[len] = '\0';
> 
> arch/um/kernel/kmsg_dump.c
> 29:	while (kmsg_dump_get_line(dumper, true, line, sizeof(line), &len)) {
> 30-		line[len] = '\0';
> 
> I guess we should fix these first and leave this patch as is?

We certainly need to fix something here, and I'd say that we
better handle it on the msg_print_text() side. There might be
more kmsg_dump_get_line() users doing `buf[len] = '\0'' in the
future.

	-ss

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Sergey Senozhatsky]

On (07/09/19 16:29), Petr Mladek wrote:
> 
> Anyway, if nobody vetoes the patch, I would schedule it for 5.4.
> We are already in the merge window and it deserves some testing
> in linux-next.
> 

I don't really want to veto it, but I'm not comfortable with fixing
off-by-one error by introducing another off-by-one error. The former
one leads to a missing message, the latter one to memory corruption.
Given that Vincent did find the code which does `buf[len] = 0x00'
[kudos to Vincent] let's have a better solution here. Otherwise, the
patch can make it to -stable via AUTOSEL machinery and then "we have
a problem".

Objections?

	-ss

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Petr Mladek]

On Wed 2019-07-10 17:19:22, Sergey Senozhatsky wrote:
> On (07/10/19 10:04), Vincent Whitchurch wrote:
> > > > [..]
> > > > 
> > > > > @@ -1318,7 +1318,7 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog,
> > > > >  		}
> > > > >  
> > > > >  		if (buf) {
> > > > > -			if (prefix_len + text_len + 1 >= size - len)
> > > > > +			if (prefix_len + text_len + 1 > size - len)
> > > > >  				break;
> > > > 
> > > > So with this patch the last byte of the buffer is 0xA. It's a bit
> > > > uncomfortable that `len', which we return from msg_print_text(),
> > > > now points one byte beyond the buffer:
> > > > 
> > > > 	buf[len++] = '\n';
> > > > 	return len;
> > > > 
> > > > This is not very common. Not sure what usually happens to kmsg_dump
> > > > buffers, but anyone who'd do a rather innocent
> > > > 
> > > > 	kmsg_dump(buf, &len);
> > > > 	buf[len] = 0x00;
> > > > 
> > > > will write to something which is not a kmsg buffer (in some cases).
> 
> [..]
> 
> > arch/powerpc/xmon/xmon.c
> > 2836:	while (kmsg_dump_get_line_nolock(&dumper, false, buf, sizeof(buf), &len)) {
> > 2837-		buf[len] = '\0';
> > 
> > arch/um/kernel/kmsg_dump.c
> > 29:	while (kmsg_dump_get_line(dumper, true, line, sizeof(line), &len)) {
> > 30-		line[len] = '\0';
> > 
> > I guess we should fix these first and leave this patch as is?
> 
> We certainly need to fix something here, and I'd say that we
> better handle it on the msg_print_text() side. There might be
> more kmsg_dump_get_line() users doing `buf[len] = '\0'' in the
> future.

I though more about it and I agree with Sergey. One unused byte does
not look worth the risk. Especially when we are talking about strings
where many people expect the trailing '\0'.

I would even modify msg_print_text() to always add the trailing '\0'.
All bytes will be used and it will be more error-proof API. I guess
that this is what Sergey meant by better handling it on the
msg_print_text() side.

Best Regards,
Petr

Re: [PATCH] printk: Do not lose last line in kmsg dump

[Steven Rostedt]

On Wed, 10 Jul 2019 14:10:49 +0200
Petr Mladek <pmladek@suse.com> wrote:

> On Wed 2019-07-10 17:19:22, Sergey Senozhatsky wrote:
 
> > > arch/powerpc/xmon/xmon.c
> > > 2836:	while (kmsg_dump_get_line_nolock(&dumper, false, buf, sizeof(buf), &len)) {
> > > 2837-		buf[len] = '\0';
> > > 
> > > arch/um/kernel/kmsg_dump.c
> > > 29:	while (kmsg_dump_get_line(dumper, true, line, sizeof(line), &len)) {
> > > 30-		line[len] = '\0';
> > > 
> > > I guess we should fix these first and leave this patch as is?  
> > 
> > We certainly need to fix something here, and I'd say that we
> > better handle it on the msg_print_text() side. There might be
> > more kmsg_dump_get_line() users doing `buf[len] = '\0'' in the
> > future.  

So basically the issues is that callers may expect that the return size
is still in the buffer and they append a '\0' to it. This is the same
issue with strncpy() and will cause the same kinds of bugs.

> 
> I though more about it and I agree with Sergey. One unused byte does
> not look worth the risk. Especially when we are talking about strings
> where many people expect the trailing '\0'.
> 
> I would even modify msg_print_text() to always add the trailing '\0'.
> All bytes will be used and it will be more error-proof API. I guess
> that this is what Sergey meant by better handling it on the
> msg_print_text() side.

I agree too. We either keep it as is and let the callers be able to add
the '\0', or we preferably add the '\0' ourselves and return the length
written (not counting the terminating '\0'), and we can then remove the
callers adding the '\0' later.

That's the safest approach.

-- Steve