[PATCH next v2 0/2] printk: fix reading beyond buffer

[PATCH next v2 0/2] printk: fix reading beyond buffer

[John Ogness]

Hello,

Marek Szyprowski reported [0] a problem with a particular printk
usage. This particular usage performs thousands of LOG_CONT calls.
The printk.c implementation was only limiting the growing record by
the maximum size available in the ringbuffer, thus creating a record
that was several kilobytes in size. This in and of itself is not
a problem.

However, the various readers used buffers that were about 1KB in
size. The ringbuffer would only fill the reader's 1KB buffer, but the
meta data stated that the message was actually much larger. The
reader code was not checking this and assumed its buffer contained
the full message.

I have solved this problem by adding the necessary check to the
functions where the situation can occur and also adding an argument
when extending records so that a maximum size is specified. This
will prevent the records from growing beyond the size that we know
our readers are using.

I did not add the check where it is certain that the reader's
buffer is large enough to contain the largest possible message.

The 2nd patch in this series reduces the size of the initial setup
buffer. I noticed it was too big while verifying all the sizes for
this series.

John Ogness

[0] https://lkml.kernel.org/r/f1651593-3579-5820-6863-5f4973d2bfdc@samsung.com

John Ogness (2):
  printk: avoid and/or handle record truncation
  printk: reduce setup_text_buf size to LOG_LINE_MAX

 kernel/printk/printk.c            | 11 +++++++++--
 kernel/printk/printk_ringbuffer.c | 12 ++++++++++--
 kernel/printk/printk_ringbuffer.h |  2 +-
 3 files changed, 20 insertions(+), 5 deletions(-)

-- 
2.20.1

[PATCH next v2 1/2] printk: avoid and/or handle record truncation

[John Ogness]

If a reader provides a buffer that is smaller than the message text,
the @text_len field of @info will have a value larger than the buffer
size. If readers blindly read @text_len bytes of data without
checking the size, they will read beyond their buffer.

Add this check to record_print_text() to properly recognize when such
truncation has occurred.

Add a maximum size argument to the ringbuffer function to extend
records so that records can not be created that are larger than the
buffer size of readers.

When extending records (LOG_CONT), do not extend records beyond
LOG_LINE_MAX since that is the maximum size available in the buffers
used by consoles and syslog.

Fixes: f5f022e53b87 ("printk: reimplement log_cont using record extension")
Signed-off-by: John Ogness <john.ogness@linutronix.de>
Reported-by: Marek Szyprowski <m.szyprowski@samsung.com>
---
 kernel/printk/printk.c            |  9 ++++++++-
 kernel/printk/printk_ringbuffer.c | 12 ++++++++++--
 kernel/printk/printk_ringbuffer.h |  2 +-
 3 files changed, 19 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 78f68b4830dc..04cf1e00478f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1357,6 +1357,13 @@ static size_t record_print_text(struct printk_record *r, bool syslog,
 	size_t len = 0;
 	char *next;
 
+	/*
+	 * If the message was truncated because the buffer was not large
+	 * enough, treat the available text as if it were the full text.
+	 */
+	if (text_len > buf_size)
+		text_len = buf_size;
+
 	prefix_len = info_print_prefix(r->info, syslog, time, prefix);
 
 	/*
@@ -1911,7 +1918,7 @@ static size_t log_output(int facility, int level, enum log_flags lflags,
 		struct printk_record r;
 
 		prb_rec_init_wr(&r, text_len);
-		if (prb_reserve_in_last(&e, prb, &r, caller_id)) {
+		if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
 			memcpy(&r.text_buf[r.info->text_len], text, text_len);
 			r.info->text_len += text_len;
 			if (lflags & LOG_NEWLINE) {
diff --git a/kernel/printk/printk_ringbuffer.c b/kernel/printk/printk_ringbuffer.c
index 13b94b92342e..2493348a1631 100644
--- a/kernel/printk/printk_ringbuffer.c
+++ b/kernel/printk/printk_ringbuffer.c
@@ -202,7 +202,8 @@
  *	// specify additional 5 bytes text space to extend
  *	prb_rec_init_wr(&r, 5);
  *
- *	if (prb_reserve_in_last(&e, &test_rb, &r, printk_caller_id())) {
+ *	// try to extend, but only if it does not exceed 32 bytes
+ *	if (prb_reserve_in_last(&e, &test_rb, &r, printk_caller_id()), 32) {
  *		snprintf(&r.text_buf[r.info->text_len],
  *			 r.text_buf_size - r.info->text_len, "hello");
  *
@@ -1309,6 +1310,7 @@ static struct prb_desc *desc_reopen_last(struct prb_desc_ring *desc_ring,
  * @rb:        The ringbuffer to re-reserve and extend data in.
  * @r:         The record structure to allocate buffers for.
  * @caller_id: The caller ID of the caller (reserving writer).
+ * @max_size:  Fail if the extended size would be greater than this.
  *
  * This is the public function available to writers to re-reserve and extend
  * data.
@@ -1343,7 +1345,7 @@ static struct prb_desc *desc_reopen_last(struct prb_desc_ring *desc_ring,
  *            @r->info->text_len after concatenating.
  */
 bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer *rb,
-			 struct printk_record *r, u32 caller_id)
+			 struct printk_record *r, u32 caller_id, unsigned int max_size)
 {
 	struct prb_desc_ring *desc_ring = &rb->desc_ring;
 	struct printk_info *info;
@@ -1389,6 +1391,9 @@ bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer
 		if (!data_check_size(&rb->text_data_ring, r->text_buf_size))
 			goto fail;
 
+		if (r->text_buf_size > max_size)
+			goto fail;
+
 		r->text_buf = data_alloc(rb, &rb->text_data_ring, r->text_buf_size,
 					 &d->text_blk_lpos, id);
 	} else {
@@ -1410,6 +1415,9 @@ bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer
 		if (!data_check_size(&rb->text_data_ring, r->text_buf_size))
 			goto fail;
 
+		if (r->text_buf_size > max_size)
+			goto fail;
+
 		r->text_buf = data_realloc(rb, &rb->text_data_ring, r->text_buf_size,
 					   &d->text_blk_lpos, id);
 	}
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index 0adaa685d1ca..5dc9d022db07 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -303,7 +303,7 @@ static inline void prb_rec_init_wr(struct printk_record *r,
 bool prb_reserve(struct prb_reserved_entry *e, struct printk_ringbuffer *rb,
 		 struct printk_record *r);
 bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer *rb,
-			 struct printk_record *r, u32 caller_id);
+			 struct printk_record *r, u32 caller_id, unsigned int max_size);
 void prb_commit(struct prb_reserved_entry *e);
 void prb_final_commit(struct prb_reserved_entry *e);
 
-- 
2.20.1

[PATCH next v2 2/2] printk: reduce setup_text_buf size to LOG_LINE_MAX

[John Ogness]

@setup_text_buf only copies the original text messages (without any
prefix or extended text). It only needs to be LOG_LINE_MAX in size.

Signed-off-by: John Ogness <john.ogness@linutronix.de>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 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 04cf1e00478f..1538df175aae 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1103,7 +1103,7 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
 	return prb_record_text_space(&e);
 }
 
-static char setup_text_buf[CONSOLE_EXT_LOG_MAX] __initdata;
+static char setup_text_buf[LOG_LINE_MAX] __initdata;
 
 void __init setup_log_buf(int early)
 {
-- 
2.20.1

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Sergey Senozhatsky]

On (20/09/30 11:07), John Ogness wrote:
[..]
> @@ -1389,6 +1391,9 @@ bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer
>  		if (!data_check_size(&rb->text_data_ring, r->text_buf_size))
>  			goto fail;
>  
> +		if (r->text_buf_size > max_size)
> +			goto fail;
> +
>  		r->text_buf = data_alloc(rb, &rb->text_data_ring, r->text_buf_size,
>  					 &d->text_blk_lpos, id);
>  	} else {
> @@ -1410,6 +1415,9 @@ bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer
>  		if (!data_check_size(&rb->text_data_ring, r->text_buf_size))
>  			goto fail;
>  
> +		if (r->text_buf_size > max_size)
> +			goto fail;
> +
>  		r->text_buf = data_realloc(rb, &rb->text_data_ring, r->text_buf_size,
>  					   &d->text_blk_lpos, id);
>  	}
[..]

>  bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer *rb,
> -			 struct printk_record *r, u32 caller_id);
> +			 struct printk_record *r, u32 caller_id, unsigned int max_size);

Isn't `max_size' always LOG_LINE_MAX?

	-ss

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[John Ogness]

On 2020-09-30, Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
> On (20/09/30 11:07), John Ogness wrote:
>>  bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer *rb,
>> -			 struct printk_record *r, u32 caller_id);
>> +			 struct printk_record *r, u32 caller_id, unsigned int max_size);
>
> Isn't `max_size' always LOG_LINE_MAX?

Yes. But I still think it makes sense that it is an argument of the
function. It is quite an important setting and hard-coding it within the
ringbuffer code might lead to hidden problems later.

John Ogness

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Petr Mladek]

On Wed 2020-09-30 12:30:50, John Ogness wrote:
> On 2020-09-30, Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
> > On (20/09/30 11:07), John Ogness wrote:
> >>  bool prb_reserve_in_last(struct prb_reserved_entry *e, struct printk_ringbuffer *rb,
> >> -			 struct printk_record *r, u32 caller_id);
> >> +			 struct printk_record *r, u32 caller_id, unsigned int max_size);
> >
> > Isn't `max_size' always LOG_LINE_MAX?
> 
> Yes. But I still think it makes sense that it is an argument of the
> function. It is quite an important setting and hard-coding it within the
> ringbuffer code might lead to hidden problems later.

I personally prefer the argument as well.

It is true that printk_ringbuffer is not a fully generic ringbuffer.
It has very special behavior so that it can be hardly be used
anywhere else.

Sometimes it is not clear what printk() requirements should be passed via
the API or hardcoded into the ring buffer code. IMHO, it depends on the code
complexity.

Anyway, I see hardcoded limit more like a hack. It limits something
somewhere so that some other code somewhere else is safe to use.

And printk.c is really bad from this point. It sometimes does not
check for overflow because it "knows" that the buffers are big
enough. But it is error prone code, especially when there are more
limits defined (pure text, prefix, extended prefix). And it
will be worse if we allow to add more optional information
into the prefix.

Best Regards,
Petr

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[John Ogness]

On 2020-09-30, Petr Mladek <pmladek@suse.com> wrote:
> Anyway, I see hardcoded limit more like a hack. It limits something
> somewhere so that some other code somewhere else is safe to use.
>
> And printk.c is really bad from this point. It sometimes does not
> check for overflow because it "knows" that the buffers are big
> enough. But it is error prone code, especially when there are more
> limits defined (pure text, prefix, extended prefix). And it
> will be worse if we allow to add more optional information
> into the prefix.

So should I post a v3 where the checks are added? Or should I add
comments where checks would be, explaining why the checks are not
needed?

John Ogness

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Petr Mladek]

On Wed 2020-09-30 13:48:56, John Ogness wrote:
> On 2020-09-30, Petr Mladek <pmladek@suse.com> wrote:
> > Anyway, I see hardcoded limit more like a hack. It limits something
> > somewhere so that some other code somewhere else is safe to use.
> >
> > And printk.c is really bad from this point. It sometimes does not
> > check for overflow because it "knows" that the buffers are big
> > enough. But it is error prone code, especially when there are more
> > limits defined (pure text, prefix, extended prefix). And it
> > will be worse if we allow to add more optional information
> > into the prefix.
> 
> So should I post a v3 where the checks are added? Or should I add
> comments where checks would be, explaining why the checks are not
> needed?

If you have these locations still in head then it would be nice
to add the checks.

But it is not urgent. We should be on the safe side. Both ways
to store new messages are limited again now.

Anyway, please do so in a followup patch. I would like to push this
patchset into linux-next ASAP so that the robots could continue
finding new bugs.

Best Regards,
Petr

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Petr Mladek]

On Wed 2020-09-30 11:07:33, John Ogness wrote:
> If a reader provides a buffer that is smaller than the message text,
> the @text_len field of @info will have a value larger than the buffer
> size. If readers blindly read @text_len bytes of data without
> checking the size, they will read beyond their buffer.
> 
> Add this check to record_print_text() to properly recognize when such
> truncation has occurred.
> 
> Add a maximum size argument to the ringbuffer function to extend
> records so that records can not be created that are larger than the
> buffer size of readers.
> 
> When extending records (LOG_CONT), do not extend records beyond
> LOG_LINE_MAX since that is the maximum size available in the buffers
> used by consoles and syslog.
> 
> Fixes: f5f022e53b87 ("printk: reimplement log_cont using record extension")
> Signed-off-by: John Ogness <john.ogness@linutronix.de>
> Reported-by: Marek Szyprowski <m.szyprowski@samsung.com>

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

Best Regards,
Petr

Re: [PATCH next v2 0/2] printk: fix reading beyond buffer

[Petr Mladek]

On Wed 2020-09-30 11:07:32, John Ogness wrote:
> Hello,
> 
> Marek Szyprowski reported [0] a problem with a particular printk
> usage. This particular usage performs thousands of LOG_CONT calls.
> The printk.c implementation was only limiting the growing record by
> the maximum size available in the ringbuffer, thus creating a record
> that was several kilobytes in size. This in and of itself is not
> a problem.
> 
> However, the various readers used buffers that were about 1KB in
> size. The ringbuffer would only fill the reader's 1KB buffer, but the
> meta data stated that the message was actually much larger. The
> reader code was not checking this and assumed its buffer contained
> the full message.
> 
> I have solved this problem by adding the necessary check to the
> functions where the situation can occur and also adding an argument
> when extending records so that a maximum size is specified. This
> will prevent the records from growing beyond the size that we know
> our readers are using.
> 
> I did not add the check where it is certain that the reader's
> buffer is large enough to contain the largest possible message.
> 
> The 2nd patch in this series reduces the size of the initial setup
> buffer. I noticed it was too big while verifying all the sizes for
> this series.
> 
> John Ogness
> 
> [0] https://lkml.kernel.org/r/f1651593-3579-5820-6863-5f4973d2bfdc@samsung.com
> 
> John Ogness (2):
>   printk: avoid and/or handle record truncation
>   printk: reduce setup_text_buf size to LOG_LINE_MAX

The patchset is committed in printk/linux.git, branch printk-rework.

Best Regards,
Petr

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Joe Perches]

On Wed, 2020-09-30 at 11:07 +0206, John Ogness wrote:
> If a reader provides a buffer that is smaller than the message text,
> the @text_len field of @info will have a value larger than the buffer
> size. If readers blindly read @text_len bytes of data without
> checking the size, they will read beyond their buffer.
> 
> Add this check to record_print_text() to properly recognize when such
> truncation has occurred.
> 
> Add a maximum size argument to the ringbuffer function to extend
> records so that records can not be created that are larger than the
> buffer size of readers.
> 
> When extending records (LOG_CONT), do not extend records beyond
> LOG_LINE_MAX since that is the maximum size available in the buffers
> used by consoles and syslog.

I still think it better to support backspace by rewinding
the buffer rather than truncation of the output.

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Sergey Senozhatsky]

On (20/09/30 13:53), Petr Mladek wrote:
> 
> Anyway, please do so in a followup patch. I would like to push this
> patchset into linux-next ASAP so that the robots could continue
> finding new bugs.

ACK.

	-ss

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Petr Mladek]

On Wed 2020-09-30 08:25:24, Joe Perches wrote:
> On Wed, 2020-09-30 at 11:07 +0206, John Ogness wrote:
> > If a reader provides a buffer that is smaller than the message text,
> > the @text_len field of @info will have a value larger than the buffer
> > size. If readers blindly read @text_len bytes of data without
> > checking the size, they will read beyond their buffer.
> > 
> > Add this check to record_print_text() to properly recognize when such
> > truncation has occurred.
> > 
> > Add a maximum size argument to the ringbuffer function to extend
> > records so that records can not be created that are larger than the
> > buffer size of readers.
> > 
> > When extending records (LOG_CONT), do not extend records beyond
> > LOG_LINE_MAX since that is the maximum size available in the buffers
> > used by consoles and syslog.
> 
> I still think it better to support backspace by rewinding
> the buffer rather than truncation of the output.

IMHO, backspace support is not worth the complexity. It might do
some fancy animation on console but it does not bring any advantage
in static logs (dmesg, journalctl).

It is possible that it worked in the past when the log buffer was
just an array of characters that were pushed to the console when
they appeared.

But I am pretty sure that it has stopped working many years ago when
the buffer 7ff9554bb578 ("printk: convert byte-buffer to
variable-length record buffer").

Best Regards,
Petr

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Joe Perches]

On Thu, 2020-10-01 at 09:26 +0200, Petr Mladek wrote:
> On Wed 2020-09-30 08:25:24, Joe Perches wrote:
> > On Wed, 2020-09-30 at 11:07 +0206, John Ogness wrote:
> > > If a reader provides a buffer that is smaller than the message text,
> > > the @text_len field of @info will have a value larger than the buffer
> > > size. If readers blindly read @text_len bytes of data without
> > > checking the size, they will read beyond their buffer.
> > > 
> > > Add this check to record_print_text() to properly recognize when such
> > > truncation has occurred.
> > > 
> > > Add a maximum size argument to the ringbuffer function to extend
> > > records so that records can not be created that are larger than the
> > > buffer size of readers.
> > > 
> > > When extending records (LOG_CONT), do not extend records beyond
> > > LOG_LINE_MAX since that is the maximum size available in the buffers
> > > used by consoles and syslog.
> > 
> > I still think it better to support backspace by rewinding
> > the buffer rather than truncation of the output.
> 
> IMHO, backspace support is not worth the complexity. It might do
> some fancy animation on console but it does not bring any advantage
> in static logs (dmesg, journalctl).
> 
> It is possible that it worked in the past when the log buffer was
> just an array of characters that were pushed to the console when
> they appeared.
> 
> But I am pretty sure that it has stopped working many years agl
> variable-length record buffer").

It's more that spinner or timer dots could fill the
buffer and any message after the spinner/dots like
success or failure is lost via truncation.

There aren't many spinners/dots, perhaps it's better
to find and delete them.

Re: [PATCH next v2 1/2] printk: avoid and/or handle record truncation

[Petr Mladek]

On Thu 2020-10-01 00:39:31, Joe Perches wrote:
> On Thu, 2020-10-01 at 09:26 +0200, Petr Mladek wrote:
> > On Wed 2020-09-30 08:25:24, Joe Perches wrote:
> > > On Wed, 2020-09-30 at 11:07 +0206, John Ogness wrote:
> > > > If a reader provides a buffer that is smaller than the message text,
> > > > the @text_len field of @info will have a value larger than the buffer
> > > > size. If readers blindly read @text_len bytes of data without
> > > > checking the size, they will read beyond their buffer.
> > > > 
> > > > Add this check to record_print_text() to properly recognize when such
> > > > truncation has occurred.
> > > > 
> > > > Add a maximum size argument to the ringbuffer function to extend
> > > > records so that records can not be created that are larger than the
> > > > buffer size of readers.
> > > > 
> > > > When extending records (LOG_CONT), do not extend records beyond
> > > > LOG_LINE_MAX since that is the maximum size available in the buffers
> > > > used by consoles and syslog.
> > > 
> > > I still think it better to support backspace by rewinding
> > > the buffer rather than truncation of the output.
> > 
> > IMHO, backspace support is not worth the complexity. It might do
> > some fancy animation on console but it does not bring any advantage
> > in static logs (dmesg, journalctl).
> > 
> > It is possible that it worked in the past when the log buffer was
> > just an array of characters that were pushed to the console when
> > they appeared.
> > 
> > But I am pretty sure that it has stopped working many years agl
> > variable-length record buffer").
> 
> It's more that spinner or timer dots could fill the
> buffer and any message after the spinner/dots like
> success or failure is lost via truncation.

Yeah, pushing existing parts of continuous lines on the console
would be nice. It would help to see that the system died in
the middle of a risky operation.

But it requires an extra code in the record based log buffer.
It actually has been there and it was removed later because it
complicated the code and did not really worked.

It will be even more complicated with the lockless ringbuffer
and console handled in kthreads.

It might be added when there is a big demand for it. But it does
not make sense to support looong lines full of spinners or dots.


> There aren't many spinners/dots, perhaps it's better
> to find and delete them.

Yeah, that would be nice cleanup.

Best Regards,
Petr