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

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

[Vincent Whitchurch]

kmsg_dump_get_buffer() is supposed to select all the youngest log
messages which fit into the provided buffer.  It determines the correct
start index by using msg_print_text() with a NULL buffer to calculate
the size of each entry.  However, when performing the actual writes,
msg_print_text() only writes the entry to the buffer if the written len
is lesser than the size of the buffer.  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.

We don't want to modify msg_print_text() to fill up the buffer and start
returning a length which is equal to the size of the buffer, since
callers of its other users, such as kmsg_dump_get_line(), depend upon
the current behaviour.

Instead, fix kmsg_dump_get_buffer() to compensate for this.

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 35 36 36 37 38  <0>[    6.456678
 00000010: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
 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  ................

Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
---
v2: Move fix to kmsg_dump_get_buffer()

 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..424abf802f02 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3274,7 +3274,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	/* move first record forward until length fits into the buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
-	while (l > size && seq < dumper->next_seq) {
+	while (l >= size && seq < dumper->next_seq) {
 		struct printk_log *msg = log_from_idx(idx);
 
 		l -= msg_print_text(msg, true, time, NULL, 0);
-- 
2.20.0

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

[Petr Mladek]

On Thu 2019-07-11 16:29:37, Vincent Whitchurch wrote:
> kmsg_dump_get_buffer() is supposed to select all the youngest log
> messages which fit into the provided buffer.  It determines the correct
> start index by using msg_print_text() with a NULL buffer to calculate
> the size of each entry.  However, when performing the actual writes,
> msg_print_text() only writes the entry to the buffer if the written len
> is lesser than the size of the buffer.  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.
> 
> We don't want to modify msg_print_text() to fill up the buffer and start
> returning a length which is equal to the size of the buffer, since
> callers of its other users, such as kmsg_dump_get_line(), depend upon
> the current behaviour.
> 
> Instead, fix kmsg_dump_get_buffer() to compensate for this.
> 
> 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 35 36 36 37 38  <0>[    6.456678
>  00000010: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
>  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  ................
> 
> Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
> ---
> v2: Move fix to kmsg_dump_get_buffer()
> 
>  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..424abf802f02 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3274,7 +3274,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
>  	/* move first record forward until length fits into the buffer */
>  	seq = dumper->cur_seq;
>  	idx = dumper->cur_idx;
> -	while (l > size && seq < dumper->next_seq) {
> +	while (l >= size && seq < dumper->next_seq) {

This cycle searches how many messages would fit into the buffer.

The patch looks like a hack using a hole that the next cycle
does not longer check the number of really stored characters.

What would happen when msg_print_text() starts adding
the trailing '\0' as suggested by
https://lkml.kernel.org/r/20190710121049.rwhk7fknfzn3cfkz@pathway.suse.cz

I would much more appreciate if we make the code more secure instead
of stretching its weakness to the limits.

BTW: What is the motivation for this fix? Is a bug report
or just some research of possible buffer overflows?

The commit message pretends that the problem is bigger than
it really is. It is about one byte and not one line.

Best Regards,
Petr

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

[Vincent Whitchurch]

On Fri, Jul 12, 2019 at 10:09:04AM +0200, Petr Mladek wrote:
> The patch looks like a hack using a hole that the next cycle
> does not longer check the number of really stored characters.
> 
> What would happen when msg_print_text() starts adding
> the trailing '\0' as suggested by
> https://lkml.kernel.org/r/20190710121049.rwhk7fknfzn3cfkz@pathway.suse.cz

I did have a look at that possibility, but I didn't see how that could
work without potentially affecting userspace users of the syslog ABI.
AFAICS the suggested change in msg_print_text() can be done in one of
three ways:

 (1) msg_print_text() adds the '\0' and includes this length both when
     it estimates the size (NULL buffer) and when it actually prints:

     If we do this:
     - kmsg_dump_get_line_nolock() would have to subtract 1 from the len
       since its callers expected that len is always smaller than the
       size of the buffer.
     - The buffers given to use via the syslog interface will now include
       a '\0', potentially affecting userspace applications which use
       this ABI.
 
 (2) msg_print_text() adds the '\0', and includes this in the length
     only when estimating the size, and not when it actually prints.

     If we do this:
     - SYSLOG_ACTION_SIZE_UNREAD tries uses the size estimate to give
       userspace a count of how many characters are present in the
       buffer, and now this count will start differing from the actual
       count that can be read, potentially affecting userspace
       applications.

 (3) msg_print_text() adds the '\0', and does not include this length
     in the result at all.

     If we do this:
     - The original kmsg dump issue is not solved, since the last line
       is still lost.

> BTW: What is the motivation for this fix? Is a bug report
> or just some research of possible buffer overflows?

The fix is not attempting to fix a buffer overflow, theoretical or
otherwise.

It's a fix for a bug in functionality which has been observed on our
systems:  We use pstore to save the kernel log when the kernel crashes,
and sometimes the log in the pstore misses the last line, and since the
last line usual says why we're panicing so it's rather important not to
miss.

> The commit message pretends that the problem is bigger than
> it really is. It is about one byte and not one line.

I'm not quite sure I follow.  The current code does fail to include the
*entire* last line.

The memcpy on line #1294 is never executed for the last line because we
stop the loop because of the check on line #1289:

  1270  static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *buf, size_t size)
  1271  {
  1272          const char *text = log_text(msg);
  1273          size_t text_size = msg->text_len;
  1274          size_t len = 0;
  1275  
  1276          do {
  1277                  const char *next = memchr(text, '\n', text_size);
  1278                  size_t text_len;
  1279  
  1280                  if (next) {
  1281                          text_len = next - text;
  1282                          next++;
  1283                          text_size -= next - text;
  1284                  } else {
  1285                          text_len = text_size;
  1286                  }
  1287  
  1288                  if (buf) {
  1289                          if (print_prefix(msg, syslog, NULL) +
  1290                              text_len + 1 > size - len)
  1291                                  break;
  1292  
  1293                          len += print_prefix(msg, syslog, buf + len);
  1294                          memcpy(buf + len, text, text_len);
  1295                          len += text_len;
  1296                          buf[len++] = '\n';
  1297                  } else {
  1298                          /* SYSLOG_ACTION_* buffer size only calculation */
  1299                          len += print_prefix(msg, syslog, NULL);
  1300                          len += text_len;
  1301                          len++;
  1302                  }

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

[Petr Mladek]

On Thu 2019-07-11 16:29:37, Vincent Whitchurch wrote:
> kmsg_dump_get_buffer() is supposed to select all the youngest log
> messages which fit into the provided buffer.  It determines the correct
> start index by using msg_print_text() with a NULL buffer to calculate
> the size of each entry.  However, when performing the actual writes,
> msg_print_text() only writes the entry to the buffer if the written len
> is lesser than the size of the buffer.  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.
> 
> We don't want to modify msg_print_text() to fill up the buffer and start
> returning a length which is equal to the size of the buffer, since
> callers of its other users, such as kmsg_dump_get_line(), depend upon
> the current behaviour.
> 
> Instead, fix kmsg_dump_get_buffer() to compensate for this.
> 
> 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 35 36 36 37 38  <0>[    6.456678
>  00000010: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
>  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  ................
> 
> Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>

I think that I need vacation. I have got lost in all the checks
and got it wrongly in the morning.

This patch fixes the calculation of messages that might fit
into the buffer. It makes sure that the function that writes
the messages will really allow to write them.

It seems to be the correct fix.

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

Best Regards,
Petr

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

[Sergey Senozhatsky]

On (07/12/19 11:12), Petr Mladek wrote:
> > 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 35 36 36 37 38  <0>[    6.456678
> >  00000010: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
> >  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  ................
> > 
> > Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
> 
> I think that I need vacation. I have got lost in all the checks
> and got it wrongly in the morning.
> 
> This patch fixes the calculation of messages that might fit
> into the buffer. It makes sure that the function that writes
> the messages will really allow to write them.
> 
> It seems to be the correct fix.
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

Looks correct to me as well.

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

	-ss

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

[Petr Mladek]

On Fri 2019-07-12 18:22:53, Sergey Senozhatsky wrote:
> On (07/12/19 11:12), Petr Mladek wrote:
> > > 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 35 36 36 37 38  <0>[    6.456678
> > >  00000010: 5d 20 42 42 42 42 42 42 42 42 31 32 33 34 35 0a  ] BBBBBBBB12345.
> > >  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  ................
> > > 
> > > Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
> > 
> > I think that I need vacation. I have got lost in all the checks
> > and got it wrongly in the morning.
> > 
> > This patch fixes the calculation of messages that might fit
> > into the buffer. It makes sure that the function that writes
> > the messages will really allow to write them.
> > 
> > It seems to be the correct fix.
> > 
> > Reviewed-by: Petr Mladek <pmladek@suse.com>
> 
> Looks correct to me as well.
> 
> Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

The patch has been committed into printk.git, branch for-5.3-fixes.

I am still a bit undecided whether to send pull request the following
week or wait for 5.4. On one hand, it is very old bug (since 3.5).
On the other hand, I think that it was not reported/fixed earlier
only because it was hard to notice. And loosing the very last message
is quite pity.

Anyway, I added stable tag.

Best Regards,
Petr

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

[Sergey Senozhatsky]

On (07/12/19 15:11), Petr Mladek wrote:
> > Looks correct to me as well.
> > 
> > Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> The patch has been committed into printk.git, branch for-5.3-fixes.
> 
> I am still a bit undecided whether to send pull request the following
> week or wait for 5.4. On one hand, it is very old bug (since 3.5).
> On the other hand, I think that it was not reported/fixed earlier
> only because it was hard to notice. And loosing the very last message
> is quite pity.

My call would be - let's wait till next merge window.

	-ss

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

[Petr Mladek]

On Sat 2019-07-13 15:03:00, Sergey Senozhatsky wrote:
> On (07/12/19 15:11), Petr Mladek wrote:
> > > Looks correct to me as well.
> > > 
> > > Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> > 
> > The patch has been committed into printk.git, branch for-5.3-fixes.
> > 
> > I am still a bit undecided whether to send pull request the following
> > week or wait for 5.4. On one hand, it is very old bug (since 3.5).
> > On the other hand, I think that it was not reported/fixed earlier
> > only because it was hard to notice. And loosing the very last message
> > is quite pity.
> 
> My call would be - let's wait till next merge window.

Thanks for your opinion.

I'll leave it for 5.4 unless there is another urgent fix that would
trigger earlier pull request.

Best Regards,
Petr