Found another buffer overflow in this code that was introduced by
e3756477aec028427fec767957c0d4b6cfb87208 trying to solve a related overflow.
strace still shows a problem:
syslog(0x3, 0x7fffd65375d0, 0x1000) = 4107
The first record output was in the middle of a LOG_CONT line:
<4>[ 2.974999] 0x0000000000000500-0x000000000000052f SystemIO conflicts with Region \GPIO 1 (20130328/utaddress-251)
This happens because when discarding records to be less than len, every line it
subtracts should be the first line which means prev should be 0. Otherwise for
example it won't include the prefix len if the last line was a LOG_CONT
record, which however will be printed because there won't be a previous line.
This patch makes sure enough records are discarded to be under len.
CC: [email protected]
Signed-off-by: Debabrata Banerjee <[email protected]>
---
kernel/printk/printk.c | 2 --
1 file changed, 2 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b1d255f..c1722d5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1067,7 +1067,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
struct printk_log *msg = log_from_idx(idx);
len -= msg_print_text(msg, prev, true, NULL, 0);
- prev = msg->flags;
idx = log_next(idx);
seq++;
}
@@ -2780,7 +2779,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
l -= msg_print_text(msg, prev, true, NULL, 0);
idx = log_next(idx);
seq++;
- prev = msg->flags;
}
/* last message in next interation */
--
1.8.3.4
Adding Kay and Greg, since the original code is from commit
7ff9554bb578 ("printk: convert byte-buffer to variable-length record
buffer") and all the "prev" flag tweaks end up building on top of
that.
The whole "prev flags" is messed up, and LOG_CONT is done very confusingly.
Why are *those* particular two "prev = msg->flags" incorrect, when
every other case where we walk the messages they are required?
The code/logic makes no sense. You remove the "prev = msg->flags" at
line 1070, when the *identical* loop just above it has it. So now the
two loops count the number of characters differently. That makes no
sense.
So I don't think this fixes the fundamental problem. I'm more inclined
to believe that LOG_CONT is wrongly set somewhere, for example because
a continuation wasn't actually originally printed due to coming from
different users or something like that.
Or at the very least I want a coherent explanation why one loop would
do this and the other would not, and why counting up *different*
numbers could possibly make sense.
Because as it is, there clearly is some problem, but the patch does
not look sensible to me.
Linus
On Thu, Feb 13, 2014 at 8:42 PM, Debabrata Banerjee <[email protected]> wrote:
> Found another buffer overflow in this code that was introduced by
> e3756477aec028427fec767957c0d4b6cfb87208 trying to solve a related overflow.
>
> strace still shows a problem:
>
> syslog(0x3, 0x7fffd65375d0, 0x1000) = 4107
>
> The first record output was in the middle of a LOG_CONT line:
>
> <4>[ 2.974999] 0x0000000000000500-0x000000000000052f SystemIO conflicts with Region \GPIO 1 (20130328/utaddress-251)
>
> This happens because when discarding records to be less than len, every line it
> subtracts should be the first line which means prev should be 0. Otherwise for
> example it won't include the prefix len if the last line was a LOG_CONT
> record, which however will be printed because there won't be a previous line.
> This patch makes sure enough records are discarded to be under len.
>
> CC: [email protected]
> Signed-off-by: Debabrata Banerjee <[email protected]>
> ---
> kernel/printk/printk.c | 2 --
> 1 file changed, 2 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index b1d255f..c1722d5 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1067,7 +1067,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
> struct printk_log *msg = log_from_idx(idx);
>
> len -= msg_print_text(msg, prev, true, NULL, 0);
> - prev = msg->flags;
> idx = log_next(idx);
> seq++;
> }
> @@ -2780,7 +2779,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
> l -= msg_print_text(msg, prev, true, NULL, 0);
> idx = log_next(idx);
> seq++;
> - prev = msg->flags;
> }
>
> /* last message in next interation */
> --
> 1.8.3.4
>
On Sun, Feb 16, 2014 at 11:28:36AM -0800, Linus Torvalds wrote:
> Adding Kay and Greg, since the original code is from commit
> 7ff9554bb578 ("printk: convert byte-buffer to variable-length record
> buffer") and all the "prev" flag tweaks end up building on top of
> that.
>
> The whole "prev flags" is messed up, and LOG_CONT is done very confusingly.
>
> Why are *those* particular two "prev = msg->flags" incorrect, when
> every other case where we walk the messages they are required?
>
> The code/logic makes no sense. You remove the "prev = msg->flags" at
> line 1070, when the *identical* loop just above it has it. So now the
> two loops count the number of characters differently. That makes no
> sense.
>
> So I don't think this fixes the fundamental problem. I'm more inclined
> to believe that LOG_CONT is wrongly set somewhere, for example because
> a continuation wasn't actually originally printed due to coming from
> different users or something like that.
>
> Or at the very least I want a coherent explanation why one loop would
> do this and the other would not, and why counting up *different*
> numbers could possibly make sense.
>
> Because as it is, there clearly is some problem, but the patch does
> not look sensible to me.
Yeah, it doesn't make much sense to me either.
Kay had a printk() test module that would stress these types of paths
out a bunch, Kay, is that module around somewhere that we could maybe
add it to the kernel tree so it could be used to test changes like this?
thanks,
greg k-h
On Sun, Feb 16, 2014 at 9:47 PM, Greg Kroah-Hartman
<[email protected]> wrote:
> On Sun, Feb 16, 2014 at 11:28:36AM -0800, Linus Torvalds wrote:
>> Adding Kay and Greg, since the original code is from commit
>> 7ff9554bb578 ("printk: convert byte-buffer to variable-length record
>> buffer") and all the "prev" flag tweaks end up building on top of
>> that.
>>
>> The whole "prev flags" is messed up, and LOG_CONT is done very confusingly.
>>
>> Why are *those* particular two "prev = msg->flags" incorrect, when
>> every other case where we walk the messages they are required?
>>
>> The code/logic makes no sense. You remove the "prev = msg->flags" at
>> line 1070, when the *identical* loop just above it has it. So now the
>> two loops count the number of characters differently. That makes no
>> sense.
>>
>> So I don't think this fixes the fundamental problem. I'm more inclined
>> to believe that LOG_CONT is wrongly set somewhere, for example because
>> a continuation wasn't actually originally printed due to coming from
>> different users or something like that.
>>
>> Or at the very least I want a coherent explanation why one loop would
>> do this and the other would not, and why counting up *different*
>> numbers could possibly make sense.
>>
>> Because as it is, there clearly is some problem, but the patch does
>> not look sensible to me.
>
> Yeah, it doesn't make much sense to me either.
>
> Kay had a printk() test module that would stress these types of paths
> out a bunch, Kay, is that module around somewhere that we could maybe
> add it to the kernel tree so it could be used to test changes like this?
The module hack only tested the new stuff, not the legacy syslog() interface.
There is a bug in syslog_print_all(). We calculate the size of the
entire buffer for the plain text output including all the needed
headers, then we start to drop messages from the start, until the
result fits into the output buffer, and we start copying it.
Some of the lines get a header printed, cont lines don't. While
dropping messages from the start, if we end up at a line that did not
get a header added in the size calculation, we still add the header
now when copying it out as the first line.
We don't account for the size of this one additional header, and
therefore might end up writing up to 18 chars (syslog + time) to many.
I'll fix that tomorrow. Dropping the prev = in the loop avoids the
problem, but it will also result in fewer messages to be copied than
we could. We only have to account for the first header.
Thanks,
Kay
Found another buffer overflow in this code that was introduced by
e3756477aec028427fec767957c0d4b6cfb87208 trying to solve a related overflow.
strace still shows a problem:
syslog(0x3, 0x7fffd65375d0, 0x1000) = 4107
The first record output was in the middle of a LOG_CONT line:
<4>[ 2.974999] 0x0000000000000500-0x000000000000052f SystemIO conflicts with Region \GPIO 1 (20130328/utaddress-251)
This happens because when discarding records to be less than size, the first
line may expand due to there being no previous record. So we must use prev = 0
to calculate if it fits or we should continue discarding.
CC: [email protected]
Signed-off-by: Debabrata Banerjee <[email protected]>
---
kernel/printk/printk.c | 18 +++++++++++++-----
1 file changed, 13 insertions(+), 5 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b1d255f..bc67990 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1063,13 +1063,17 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
seq = clear_seq;
idx = clear_idx;
prev = 0;
- while (len > size && seq < log_next_seq) {
+ while (seq < log_next_seq) {
struct printk_log *msg = log_from_idx(idx);
- len -= msg_print_text(msg, prev, true, NULL, 0);
- prev = msg->flags;
idx = log_next(idx);
seq++;
+
+ if (len - msg_print_text(msg, 0, true, NULL, 0) <= size)
+ break;
+
+ len -= msg_print_text(msg, prev, true, NULL, 0);
+ prev = msg->flags;
}
/* last message fitting into this dump */
@@ -2774,12 +2778,16 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
seq = dumper->cur_seq;
idx = dumper->cur_idx;
prev = 0;
- while (l > size && seq < dumper->next_seq) {
+ while (seq < dumper->next_seq) {
struct printk_log *msg = log_from_idx(idx);
- l -= msg_print_text(msg, prev, true, NULL, 0);
idx = log_next(idx);
seq++;
+
+ if ( l - msg_print_text(msg, 0, true, NULL, 0) <= size)
+ break;
+
+ l -= msg_print_text(msg, prev, true, NULL, 0);
prev = msg->flags;
}
--
1.8.3.4
On 2/16/14, 2:28 PM, "Linus Torvalds" <[email protected]>
wrote:
>Why are *those* particular two "prev = msg->flags" incorrect, when
>every other case where we walk the messages they are required?
>
>The code/logic makes no sense. You remove the "prev = msg->flags" at
>line 1070, when the *identical* loop just above it has it. So now the
>two loops count the number of characters differently. That makes no
>sense.
>
>So I don't think this fixes the fundamental problem. I'm more inclined
>to believe that LOG_CONT is wrongly set somewhere, for example because
>a continuation wasn't actually originally printed due to coming from
>different users or something like that.
>
>Or at the very least I want a coherent explanation why one loop would
>do this and the other would not, and why counting up *different*
>numbers could possibly make sense.
The explanation is: the loops look identical but they are not. When a
record is printed first, its size can expand due to adding the prefix and
timestamp. The second loop is calculating len with the first line printed
possibly changing every iteration.
>
>Because as it is, there clearly is some problem, but the patch does
>not look sensible to me.
You are right, the patch is still flawed, sending V2.
-Debabrata
On Sun, Feb 16, 2014 at 3:23 PM, Banerjee, Debabrata
<[email protected]> wrote:
>
> The explanation is: the loops look identical but they are not. When a
> record is printed first, its size can expand due to adding the prefix and
> timestamp. The second loop is calculating len with the first line printed
> possibly changing every iteration.
That still makes zero sense.
The size should damn well not change, because we *should* be calling
it with the exact same flags. If the size changes, something is wrong.
The logic is:
- first traverse all log indexes to find out the total length
- then traverse *again* all the indexes, until you have traversed
enough that the remainder fits in the given buffer size.
For this to make sense, that second pass absolutely *has* to use the
exact same lengths as the first pass did. Otherwise the whole logic is
totally broken.
Now, *once* you have found the right record (so that the rest should
fit), the problem is that the *third* loop (that traverses that "rest"
part) is now done with a "prev" value that does not match the original
"let's figure out the size".
So my suspicion is that the *real* bug is that
prev = 0;
before that *third* loop, because it means that the first time through
that loop (when we did *not* reset "seq/idx" to the beginning, we use
the wrong "prev" value.
So my (totally and utterly untested, and obviously whitespace-damaged)
suggested patch would be something along the lines of this:
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b1d255f04135..053c3c1a4061 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1076,7 +1076,6 @@ static int syslog_print_all(char __user
*buf, int size, bool clear)
next_seq = log_next_seq;
len = 0;
- prev = 0;
while (len >= 0 && seq < next_seq) {
struct printk_log *msg = log_from_idx(idx);
int textlen;
because at least this makes sense. It means that "prev" is only zero
when we start from "clear_idx", at all other times it's actually the
msg->flags of the previous message.
But maybe I'm missing something. That code really is messy. But
clearing "prev" there in the middle really looks wrong to me.
Linus
On 2/16/14, 6:59 PM, "Linus Torvalds" <[email protected]>
wrote:
>On Sun, Feb 16, 2014 at 3:23 PM, Banerjee, Debabrata
><[email protected]> wrote:
>>
>> The explanation is: the loops look identical but they are not. When a
>> record is printed first, its size can expand due to adding the prefix
>>and
>> timestamp. The second loop is calculating len with the first line
>>printed
>> possibly changing every iteration.
>
>That still makes zero sense.
>
>The size should damn well not change, because we *should* be calling
>it with the exact same flags. If the size changes, something is wrong.
The problem is that it starts discarding records from the top of the list,
and the size of the first line is based on the previous line. When we
discard the *first* line off the list, then the size of the next line can
change since it is the new first line. My v1 patch was flawed because it
didn't consider just the first line.
>So my suspicion is that the *real* bug is that
>
> prev = 0;
>
>before that *third* loop, because it means that the first time through
>that loop (when we did *not* reset "seq/idx" to the beginning, we use
>the wrong "prev" value.
No that can't be right, the prev value after every loop is the msg->flags
from the *last* line in the list, which has no relation to the *first*, so
reusing it for the top of the next loop is nonsense. seq is not reset
because the second loop seeks to the seq where the third loop starts
printing.
I think I really fixed it properly with my v2 patch, please take a look.
-Debabrata
On Sun, Feb 16, 2014 at 4:19 PM, Banerjee, Debabrata
<[email protected]> wrote:
>
> No that can't be right, the prev value after every loop is the msg->flags
> from the *last* line in the list, which has no relation to the *first*, so
> reusing it for the top of the next loop is nonsense.
Please, Debabrata, humor me, and just try the patch.
And try reading the source code. Because your statement is BS.
The third loop does *not* start again from the first line! It
*continues* from where the second loop ended. Which is exactly why
clearing "prev" is *wrong*. Because the *last* line that the second
loop processes is indeed the previous line before the *first* line
that the third loop starts processing.
No, I haven't tested my patch, and maybe it's broken for some subtle
reason I'm missing too. But neither of your patches really make sense,
although I can believe that your second patch happens to get the
buffer size right almost by accident. Why? It's by virtue of the
"prefix" for a line generally being the same length, so when you
discount the prefix of the last line that you *don't* print, you by
accident get as much room as the - extraneous - prefix of the *next*
line that then actually gets copied. See?
(Btw, just to clarify: kmsg_dump_get_buffer() has the exact same logic
and the exact same bug, so as with your patches, you should remove the
"prev = 0" from before the third loop from that function too. Because
exactly as with syslog_print_all(), the third loop *continues* where
the second loop stops, and thus clearing "prev" is actually wrong).
That extended patch attached, now without whitespace damage. But still
completely and utterly untested.
Linus
Found another buffer overflow in this code that was introduced by
e3756477aec028427fec767957c0d4b6cfb87208 trying to solve a related overflow.
strace still shows a problem:
syslog(0x3, 0x7fffd65375d0, 0x1000) = 4107
The first record output was in the middle of a LOG_CONT line:
<4>[ 2.974999] 0x0000000000000500-0x000000000000052f SystemIO conflicts with Region \GPIO 1 (20130328/utaddress-251)
This happens because when discarding records to be less than size, the first
line may expand due to there being no previous record. So we must use prev = 0
to calculate if it fits or we should continue discarding.
v3: fix whitespace
v2: fix loop properly
CC: [email protected]
Signed-off-by: Debabrata Banerjee <[email protected]>
---
kernel/printk/printk.c | 18 +++++++++++++-----
1 file changed, 13 insertions(+), 5 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b1d255f..e95c7b4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1063,13 +1063,17 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
seq = clear_seq;
idx = clear_idx;
prev = 0;
- while (len > size && seq < log_next_seq) {
+ while (seq < log_next_seq) {
struct printk_log *msg = log_from_idx(idx);
- len -= msg_print_text(msg, prev, true, NULL, 0);
- prev = msg->flags;
idx = log_next(idx);
seq++;
+
+ if (len - msg_print_text(msg, 0, true, NULL, 0) <= size)
+ break;
+
+ len -= msg_print_text(msg, prev, true, NULL, 0);
+ prev = msg->flags;
}
/* last message fitting into this dump */
@@ -2774,12 +2778,16 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
seq = dumper->cur_seq;
idx = dumper->cur_idx;
prev = 0;
- while (l > size && seq < dumper->next_seq) {
+ while (seq < dumper->next_seq) {
struct printk_log *msg = log_from_idx(idx);
- l -= msg_print_text(msg, prev, true, NULL, 0);
idx = log_next(idx);
seq++;
+
+ if (l - msg_print_text(msg, 0, true, NULL, 0) <= size)
+ break;
+
+ l -= msg_print_text(msg, prev, true, NULL, 0);
prev = msg->flags;
}
--
1.8.3.4
On Mon, Feb 17, 2014 at 1:41 AM, Linus Torvalds
<[email protected]> wrote:
> On Sun, Feb 16, 2014 at 4:19 PM, Banerjee, Debabrata
> <[email protected]> wrote:
> The third loop does *not* start again from the first line! It
> *continues* from where the second loop ended. Which is exactly why
> clearing "prev" is *wrong*. Because the *last* line that the second
> loop processes is indeed the previous line before the *first* line
> that the third loop starts processing.
>
> No, I haven't tested my patch, and maybe it's broken for some subtle
> reason I'm missing too.
That should avoid the overflow, yes. I expect it will not print the
first line with a prefix, which we probably should.?
Kay
On Sun, Feb 16, 2014 at 4:50 PM, Kay Sievers <[email protected]> wrote:
>
> That should avoid the overflow, yes. I expect it will not print the
> first line with a prefix, which we probably should.?
Well, it's not printing out the prefix, but it's also not printing out
the whole first part of the line, so quite frankly, I think that's
actually "more correct".
After all, it has already skipped the beginning of the line.
Prepending the prefix, then skipping part of the line, and then
printing the last part, that sounds truly insane, no?
This isn't even new behaviour - that's how it all worked back when it
was all a byte stream (except then it was *purely* about that byte
stream, so it could literally start anywhere in the line, including
partial prefixes etc).
Of course, an alternative approach - if we really want to always have
full lines - is to skip any partial lines at the beginning of the
output entirely. So not just drop the prefix, but drop the LOG_CONT
parts too. But since (as mentioned), we've never really guaranteed
that the log starts at line boundaries, I'm not sure what the
advantage would really be..
Linus
On Mon, Feb 17, 2014 at 1:57 AM, Linus Torvalds
<[email protected]> wrote:
> On Sun, Feb 16, 2014 at 4:50 PM, Kay Sievers <[email protected]> wrote:
>>
>> That should avoid the overflow, yes. I expect it will not print the
>> first line with a prefix, which we probably should.?
>
> Well, it's not printing out the prefix, but it's also not printing out
> the whole first part of the line, so quite frankly, I think that's
> actually "more correct".
>
> After all, it has already skipped the beginning of the line.
> Prepending the prefix, then skipping part of the line, and then
> printing the last part, that sounds truly insane, no?
Yeah, it depends on the idea of what a "line" is; being it a single
printk() call or a reconstructed continuation line, which happens when
printk calls could not be merged for some reason into a single record.
But sure, your patch, it sounds fine to just skip the prefix.
The syslog() dump interface never made any promises, and it is not
used that much anymore today (even dmesg switched away from it since
quite a while).
For the dumpers, who might use that interface to "page" through the
data, not printing the prefix sounds actually like the better option
looking at the stream of pages they ask for.
Kay
On Mon, Feb 17, 2014 at 2:19 AM, Kay Sievers <[email protected]> wrote:
> On Mon, Feb 17, 2014 at 1:57 AM, Linus Torvalds
> <[email protected]> wrote:
>> On Sun, Feb 16, 2014 at 4:50 PM, Kay Sievers <[email protected]> wrote:
>>>
>>> That should avoid the overflow, yes. I expect it will not print the
>>> first line with a prefix, which we probably should.?
>>
>> Well, it's not printing out the prefix, but it's also not printing out
>> the whole first part of the line, so quite frankly, I think that's
>> actually "more correct".
>>
>> After all, it has already skipped the beginning of the line.
>> Prepending the prefix, then skipping part of the line, and then
>> printing the last part, that sounds truly insane, no?
>
> Yeah, it depends on the idea of what a "line" is; being it a single
> printk() call or a reconstructed continuation line, which happens when
> printk calls could not be merged for some reason into a single record.
>
> But sure, your patch, it sounds fine to just skip the prefix.
>
> The syslog() dump interface never made any promises, and it is not
> used that much anymore today (even dmesg switched away from it since
> quite a while).
>
> For the dumpers, who might use that interface to "page" through the
> data, not printing the prefix sounds actually like the better option
> looking at the stream of pages they ask for.
Your patch seems to work fine here. We now start in the middle of a
cont *line*, with the next cont *record*; do not print the header, and
also do not print more than we should:
syslog(SYSLOG_ACTION_READ_ALL, "<6>[ 73.671533] ---\n<6>[
73.673677] ...", 1088) = 704
syslog(SYSLOG_ACTION_READ_ALL, "268---------...", 1089) = 1089
syslog(SYSLOG_ACTION_READ_ALL, "268---------... 1090) = 1089
The current code before the patch does this:
syslog(SYSLOG_ACTION_READ_ALL, "<4>[ 210.190007]
268---------26"..., 445) = 463
Kay
On 2/16/14, 7:41 PM, "Linus Torvalds" <[email protected]>
wrote:
>On Sun, Feb 16, 2014 at 4:19 PM, Banerjee, Debabrata
><[email protected]> wrote:
>>
>> No that can't be right, the prev value after every loop is the
>>msg->flags
>> from the *last* line in the list, which has no relation to the *first*,
>>so
>> reusing it for the top of the next loop is nonsense.
>
>Please, Debabrata, humor me, and just try the patch.
>
>And try reading the source code. Because your statement is BS.
...
>No, I haven't tested my patch, and maybe it's broken for some subtle
>reason I'm missing too.
Yes my explanation was wrong, your patch works for me. I assumed printing
the prefix was desired, but if not, great.
-Debabrata