Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
msg_print_text() would only write up to size-1 bytes into the
provided buffer. Some callers expect this behavior and append
a terminator to returned string. In particular:
arch/powerpc/xmon/xmon.c:dump_log_buf()
arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
msg_print_text() has been replaced by record_print_text(), which
currently fills the full size of the buffer. This causes a
buffer overflow for the above callers.
Change record_print_text() so that it will only use size-1 bytes
for text data. Also, for paranoia sakes, add a terminator after
the text data.
And finally, document this behavior so that it is clear that only
size-1 bytes are used and a terminator is added.
Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
Signed-off-by: John Ogness <[email protected]>
---
kernel/printk/printk.c | 35 +++++++++++++++++++++++++++--------
1 file changed, 27 insertions(+), 8 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ffdd0dc7ec6d..73f9eae19f05 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1293,9 +1293,15 @@ static size_t info_print_prefix(const struct printk_info *info, bool syslog,
* - Add prefix for each line.
* - Add the trailing newline that has been removed in vprintk_store().
* - Drop truncated lines that do not longer fit into the buffer.
+ * - Add a trailing newline.
+ * - Add a string terminator.
+ *
+ * Since the produced string is always terminated, the maximum possible
+ * return value is @r->text_buf_size - 1;
*
* Return: The length of the updated/prepared text, including the added
- * prefixes and the newline. The dropped line(s) are not counted.
+ * prefixes and the newline. The terminator is not counted. The dropped
+ * line(s) are not counted.
*/
static size_t record_print_text(struct printk_record *r, bool syslog,
bool time)
@@ -1338,26 +1344,31 @@ static size_t record_print_text(struct printk_record *r, bool syslog,
/*
* Truncate the text if there is not enough space to add the
- * prefix and a trailing newline.
+ * prefix and a trailing newline and a terminator.
*/
- if (len + prefix_len + text_len + 1 > buf_size) {
+ if (len + prefix_len + text_len + 1 + 1 > buf_size) {
/* Drop even the current line if no space. */
- if (len + prefix_len + line_len + 1 > buf_size)
+ if (len + prefix_len + line_len + 1 + 1 > buf_size)
break;
- text_len = buf_size - len - prefix_len - 1;
+ text_len = buf_size - len - prefix_len - 1 - 1;
truncated = true;
}
memmove(text + prefix_len, text, text_len);
memcpy(text, prefix, prefix_len);
+ /*
+ * Increment the prepared length to include the text and
+ * prefix that were just moved+copied. Also increment for the
+ * newline at the end of this line. If this is the last line,
+ * there is no newline, but it will be added immediately below.
+ */
len += prefix_len + line_len + 1;
-
if (text_len == line_len) {
/*
- * Add the trailing newline removed in
- * vprintk_store().
+ * This is the last line. Add the trailing newline
+ * removed in vprintk_store().
*/
text[prefix_len + line_len] = '\n';
break;
@@ -1382,6 +1393,14 @@ static size_t record_print_text(struct printk_record *r, bool syslog,
text_len -= line_len + 1;
}
+ /*
+ * If a buffer was provided, it will be terminated. Space for the
+ * string terminator is guaranteed to be available. The terminator is
+ * not counted in the return value.
+ */
+ if (buf_size > 0)
+ text[len] = 0;
+
return len;
}
--
2.20.1
On Thu 2021-01-14 18:10:12, John Ogness wrote:
> Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> msg_print_text() would only write up to size-1 bytes into the
> provided buffer. Some callers expect this behavior and append
> a terminator to returned string. In particular:
>
> arch/powerpc/xmon/xmon.c:dump_log_buf()
> arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
>
> msg_print_text() has been replaced by record_print_text(), which
> currently fills the full size of the buffer. This causes a
> buffer overflow for the above callers.
>
> Change record_print_text() so that it will only use size-1 bytes
> for text data. Also, for paranoia sakes, add a terminator after
> the text data.
>
> And finally, document this behavior so that it is clear that only
> size-1 bytes are used and a terminator is added.
>
> Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
> Signed-off-by: John Ogness <[email protected]>
Reviewed-by: Petr Mladek <[email protected]>
Best Regards,
Petr
On Fri 2021-01-15 13:04:37, Petr Mladek wrote:
> On Thu 2021-01-14 18:10:12, John Ogness wrote:
> > Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> > msg_print_text() would only write up to size-1 bytes into the
> > provided buffer. Some callers expect this behavior and append
> > a terminator to returned string. In particular:
> >
> > arch/powerpc/xmon/xmon.c:dump_log_buf()
> > arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
> >
> > msg_print_text() has been replaced by record_print_text(), which
> > currently fills the full size of the buffer. This causes a
> > buffer overflow for the above callers.
> >
> > Change record_print_text() so that it will only use size-1 bytes
> > for text data. Also, for paranoia sakes, add a terminator after
> > the text data.
> >
> > And finally, document this behavior so that it is clear that only
> > size-1 bytes are used and a terminator is added.
> >
> > Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
> > Signed-off-by: John Ogness <[email protected]>
I forgot one thing. We should add stable here:
Cc: [email protected] # 5.10+
No need to resend the patch. I'll add it when pushing the patch.
Best Regards,
Petr
Hi Petr,
I noticed some minor errors in the commit log and comments...
On 2021-01-14, John Ogness <[email protected]> wrote:
> Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> msg_print_text()
The correct commit where the change was made is: 896fbe20b4e2333fb55
("printk: use the lockless ringbuffer")
> would only write up to size-1 bytes into the
> provided buffer. Some callers expect this behavior and append
> a terminator to returned string. In particular:
>
> arch/powerpc/xmon/xmon.c:dump_log_buf()
> arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
>
> msg_print_text() has been replaced by record_print_text(), which
> currently fills the full size of the buffer. This causes a
> buffer overflow for the above callers.
>
> Change record_print_text() so that it will only use size-1 bytes
> for text data. Also, for paranoia sakes, add a terminator after
> the text data.
>
> And finally, document this behavior so that it is clear that only
> size-1 bytes are used and a terminator is added.
>
> Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
Ditto for Fixes tag:
896fbe20b4e2333fb55 ("printk: use the lockless ringbuffer")
> Signed-off-by: John Ogness <[email protected]>
> ---
> kernel/printk/printk.c | 35 +++++++++++++++++++++++++++--------
> 1 file changed, 27 insertions(+), 8 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ffdd0dc7ec6d..73f9eae19f05 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1293,9 +1293,15 @@ static size_t info_print_prefix(const struct printk_info *info, bool syslog,
> * - Add prefix for each line.
> * - Add the trailing newline that has been removed in vprintk_store().
> * - Drop truncated lines that do not longer fit into the buffer.
> + * - Add a trailing newline.
> + * - Add a string terminator.
I didn't realize that the newline was already listed (since it was out
of order). I recommend these comments changing to:
- Add prefix for each line.
- Drop truncated lines that no longer fit into the buffer.
- Add the trailing newline that has been removed in vprintk_store().
- Add a string terminator.
Can you fixup the patch for the commit or do you need a v2?
John Ogness
On Fri 2021-01-15 15:22:03, John Ogness wrote:
> Hi Petr,
>
> I noticed some minor errors in the commit log and comments...
>
> On 2021-01-14, John Ogness <[email protected]> wrote:
> > Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> > msg_print_text()
>
> Can you fixup the patch for the commit or do you need a v2?
I could fix these when pushing ;-)
Best Regards,
Petr
On (21/01/15 13:07), Petr Mladek wrote:
> On Fri 2021-01-15 13:04:37, Petr Mladek wrote:
> > On Thu 2021-01-14 18:10:12, John Ogness wrote:
> > > Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> > > msg_print_text() would only write up to size-1 bytes into the
> > > provided buffer. Some callers expect this behavior and append
> > > a terminator to returned string. In particular:
> > >
> > > arch/powerpc/xmon/xmon.c:dump_log_buf()
> > > arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
> > >
> > > msg_print_text() has been replaced by record_print_text(), which
> > > currently fills the full size of the buffer. This causes a
> > > buffer overflow for the above callers.
> > >
> > > Change record_print_text() so that it will only use size-1 bytes
> > > for text data. Also, for paranoia sakes, add a terminator after
> > > the text data.
> > >
> > > And finally, document this behavior so that it is clear that only
> > > size-1 bytes are used and a terminator is added.
> > >
> > > Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
> > > Signed-off-by: John Ogness <[email protected]>
John, how did you spot these problems?
FWIW, Acked-by: Sergey Senozhatsky <[email protected]>
> I forgot one thing. We should add stable here:
>
> Cc: [email protected] # 5.10+
Good point.
-ss
On 2021-01-19, Sergey Senozhatsky <[email protected]> wrote:
> John, how did you spot these problems?
I am preparing my series to remove the logbuf_lock, which also refactors
and consolidates code from syslog_print_all() and
kmsg_dump_get_buffer(). While testing/verifying my series, I noticed the
these oddities in the semantics and decided I should research where they
came from and if they were actually necessary.
I wouldn't say the oddities are necessary (in fact, they are quite
annoying), but we have decided to keep them in out of fear of breaking
out-of-tree modules and/or interesting userspace code.
One positive effect of the rework is that we are finding these oddities
and documenting them. I think you and Petr are going down a similar path
with the console registration stuff now.
John
On (21/01/19 10:00), John Ogness wrote:
> On 2021-01-19, Sergey Senozhatsky <[email protected]> wrote:
> > John, how did you spot these problems?
>
> I am preparing my series to remove the logbuf_lock, which also refactors
> and consolidates code from syslog_print_all() and
> kmsg_dump_get_buffer(). While testing/verifying my series, I noticed the
> these oddities in the semantics and decided I should research where they
> came from and if they were actually necessary.
Any chance you can put those tests somewhere public so that we can
run them regularly? (say, before Petr sends out a pull request to
Linus.)
> I wouldn't say the oddities are necessary (in fact, they are quite
> annoying), but we have decided to keep them in out of fear of breaking
> out-of-tree modules and/or interesting userspace code.
Sure.
> One positive effect of the rework is that we are finding these oddities
> and documenting them.
Absolutely agree.
-ss
On Tue 2021-01-19 09:44:56, Sergey Senozhatsky wrote:
> On (21/01/15 13:07), Petr Mladek wrote:
> > On Fri 2021-01-15 13:04:37, Petr Mladek wrote:
> > > On Thu 2021-01-14 18:10:12, John Ogness wrote:
> > > > Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> > > > msg_print_text() would only write up to size-1 bytes into the
> > > > provided buffer. Some callers expect this behavior and append
> > > > a terminator to returned string. In particular:
> > > >
> > > > arch/powerpc/xmon/xmon.c:dump_log_buf()
> > > > arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
> > > >
> > > > msg_print_text() has been replaced by record_print_text(), which
> > > > currently fills the full size of the buffer. This causes a
> > > > buffer overflow for the above callers.
> > > >
> > > > Change record_print_text() so that it will only use size-1 bytes
> > > > for text data. Also, for paranoia sakes, add a terminator after
> > > > the text data.
> > > >
> > > > And finally, document this behavior so that it is clear that only
> > > > size-1 bytes are used and a terminator is added.
> > > >
> > > > Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
> > > > Signed-off-by: John Ogness <[email protected]>
>
> John, how did you spot these problems?
>
> FWIW, Acked-by: Sergey Senozhatsky <[email protected]>
The patch has been committed into printk/linux.git, branch
printk-rework.
Best Regards,
Petr
On 2021-01-19, Sergey Senozhatsky <[email protected]> wrote:
>>> John, how did you spot these problems?
>>
>> I am preparing my series to remove the logbuf_lock, which also
>> refactors and consolidates code from syslog_print_all() and
>> kmsg_dump_get_buffer(). While testing/verifying my series, I noticed
>> the these oddities in the semantics and decided I should research
>> where they came from and if they were actually necessary.
>
> Any chance you can put those tests somewhere public so that we can
> run them regularly?
I have a collection of hacked-together tools that I use to test most of
the various interfaces of printk. I would need to clean them up if they
should be used for any kind of automated regression testing.
And where should I make such things available? I could put them in a
repo in the Linutronix github account (like I did for the ringbuffer
stress testing tool). (??)
John
On Tue 2021-01-19 12:50:47, John Ogness wrote:
> On 2021-01-19, Sergey Senozhatsky <[email protected]> wrote:
> >>> John, how did you spot these problems?
> >>
> >> I am preparing my series to remove the logbuf_lock, which also
> >> refactors and consolidates code from syslog_print_all() and
> >> kmsg_dump_get_buffer(). While testing/verifying my series, I noticed
> >> the these oddities in the semantics and decided I should research
> >> where they came from and if they were actually necessary.
> >
> > Any chance you can put those tests somewhere public so that we can
> > run them regularly?
Great idea.
> I have a collection of hacked-together tools that I use to test most of
> the various interfaces of printk. I would need to clean them up if they
> should be used for any kind of automated regression testing.
Sounds good. We could even help with the clean up. This kind of code
always need it when it was not written for public use from scratch.
> And where should I make such things available? I could put them in a
> repo in the Linutronix github account (like I did for the ringbuffer
> stress testing tool). (??)
Sounds good as well.
Best Regards,
Petr
John Ogness <[email protected]> writes:
> Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> msg_print_text() would only write up to size-1 bytes into the
> provided buffer. Some callers expect this behavior and append
> a terminator to returned string. In particular:
>
> arch/powerpc/xmon/xmon.c:dump_log_buf()
> arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
>
> msg_print_text() has been replaced by record_print_text(), which
> currently fills the full size of the buffer. This causes a
> buffer overflow for the above callers.
>
> Change record_print_text() so that it will only use size-1 bytes
> for text data. Also, for paranoia sakes, add a terminator after
> the text data.
>
> And finally, document this behavior so that it is clear that only
> size-1 bytes are used and a terminator is added.
>
> Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
> Signed-off-by: John Ogness <[email protected]>
> ---
> [..]
I'm seeing crashes on s390x with this patch while running the glibc
testsuite. The glibc test suite triggers a few FPU exceptions which
are printed to the kernel log by default. Looking at the crash dump,
i see that the console_drivers pointer seems to be overwritten while
printing that (user space) warning:
crash> print *console_drivers
$1 = {
name = "\247\071\377\373\354!\004\214\000\331\300\345\000\033\353_",
write = 0xa7190001eb119078,
read = 0xe6e320b0050090,
device = 0xa51e0010a7210001,
unblank = 0xa7291000b9e28012,
setup = 0xe320f0a00004e320,
exit = 0x208e0094eb112000,
match = 0xcec1c006e017f,
flags = -4984,
index = 133,
cflag = 8143136,
data = 0x800458108004ec12,
next = 0x5007eaf000000
}
crash> x/16i console_drivers
0x79009700: lghi %r3,-5
0x79009704: aghik %r2,%r1,1164
0x7900970a: brasl %r14,0x79386dc8
0x79009710: lghi %r1,1
0x79009714: laog %r1,%r1,120(%r9)
0x7900971a: llgc %r2,5(%r11)
0x79009720: llilh %r1,16
0x79009724: tmll %r2,1
0x79009728: lghi %r2,4096
0x7900972c: locgre %r1,%r2
0x79009730: lg %r2,160(%r15)
0x79009736: llc %r2,142(%r2)
0x7900973c: srlg %r1,%r1,0(%r2)
0x79009742: clij %r1,1,12,0x7900981e
0x79009748: cgij %r8,0,8,0x79009852
0x7900974e: la %r2,4(%r8)
crash> sym 0x79009700
79009700 (t) iomap_finish_ioend+192
/usr/src/debug/kernel-5.10.fc33/linux-5.11.0-20210122.rc4.git0.9f29bd8b2e71.300.fc33.s390x/./include/linux/pagemap.h:
59
So somehow the pointer for console_drivers changes.
I can't provide the normal kernel crash output as printk is no longer
working, but in crash the backtrace looks like this:
crash> bt
PID: 859915 TASK: dad24000 CPU: 9 COMMAND: "ld.so.1"
LOWCORE INFO:
-psw : 0x0002000180000000 0x0000000078c8400e
-function : stop_run at 78c8400e
-prefix : 0x0041e000
-cpu timer: 0x7ffff953a957e166
-clock cmp: 0xd92876863ac66b00
-general registers:
0xf0f0f0f000000000 0x0000000078c8400e
0x0000000079984830 0x0000000079984830
0x0000000079ac62c0 0x0000000000000002
0x0000000000000038 000000000000000000
0x000000007a19157e 000000000000000000
0x00000000fffffffa 000000000000000000
0x00000000dad24000 000000000000000000
0x0000000078c8416e 0x00000380033136f0
-access registers:
0x7d5b4da0 0xa2a795c0 0000000000 0000000000
0000000000 0000000000 0000000000 0000000000
0000000000 0000000000 0000000000 0000000000
0000000000 0000000000 0000000000 0000000000
-control registers:
0x00a0000014966a10 0x000000007a15c007
0x000000000001d0a0 000000000000000000
0x000000000000ffff 0x000000000001d080
0x000000003b000000 0x00000001f29b81c7
0x0000000000008000 000000000000000000
000000000000000000 000000000000000000
000000000000000000 0x000000007a15c007
0x00000000db000000 0x000000000001d0c0
-floating point registers:
0x5faaaaabeb67f92f 0x0007fffffffffff8
0x40400000eb67f000 000000000000000000
0x0000000000000007 0x0000006400000000
0x000002aa2a63f028 0x000000000963cf85
0x000000002a642c60 000000000000000000
0x7f85516ceb67f222 0x000003ffeb67f528
0x000003ffeb67f230 0x0000000100000000
0x000003ffeb67f21d 0x000002aa28d2d970
#0 [38003313710] stop_run at 78c8400e
#1 [38003313728] atomic_notifier_call_chain at 78ced536
#2 [38003313778] panic at 7974aeca
#3 [38003313818] die at 78c897ea
#4 [38003313880] do_no_context at 78c9b230
#5 [380033138b8] pgm_check_handler at 7976438c
PSW: 0404c00180000000 0000000078d304ba (kmsg_dump_rewind+290)
GPRS: 0000000000000020 0000000000000000 0000000000000000 00000000ffffec88
000000000000000e 00000000793f4800 0000000000000224 0000000000000000
0000000000000000 0000000000000000 0000000000000224 0005007eaf000000
00000000dad24000 0000000000000000 0000038003313a68 0000038003313a18
#0 [38003313a68] console_unlock at 78d3158e
#1 [38003313b48] vprintk_emit at 78d32f50
#2 [38003313ba8] vprintk_default at 78d32f9e
#3 [38003313c00] printk at 7974bfae
#4 [38003313c90] show_code at 78c8588e
#5 [38003313de0] show_registers at 7974a26e
#6 [38003313e70] show_regs at 78c8961e
#7 [38003313ea0] pgm_check_handler at 7976438c
PSW: 0705300080000000 000000007d7983b2 (user space)
GPRS: 0000000000000000 000000007d798360 0000000000000010 000003ff00000004
000000007f854dd0 000000007d7e9788 000003ff00401b30 000000007f854ff8
000003ff00000000 000003ff7d5b4da0 000003ff00000000 000003ff00000010
000003ff004022c6 000003ff004024b0 0000000080401796 000000007f854de8
kmsg_dump_rewind+290 is:
if (!(con->flags & CON_ENABLED))
continue;
in kernel/printk/printk.c:1845
I haven't dived into whether our show_code() is doing something wrong
which was covered in the past or whether that's because of the patch
above but wanted to make you aware of that in case you have an idea.
Otherwise i have to dig into the code.
Thanks
Sven
On 2021-01-22, Sven Schnelle <[email protected]> wrote:
> I'm seeing crashes on s390x with this patch while running the glibc
> testsuite. The glibc test suite triggers a few FPU exceptions which
> are printed to the kernel log by default. Looking at the crash dump,
> i see that the console_drivers pointer seems to be overwritten while
> printing that (user space) warning:
>
> crash> print *console_drivers
> $1 = {
> name = "\247\071\377\373\354!\004\214\000\331\300\345\000\033\353_",
> write = 0xa7190001eb119078,
> read = 0xe6e320b0050090,
> device = 0xa51e0010a7210001,
> unblank = 0xa7291000b9e28012,
> setup = 0xe320f0a00004e320,
> exit = 0x208e0094eb112000,
> match = 0xcec1c006e017f,
> flags = -4984,
> index = 133,
> cflag = 8143136,
> data = 0x800458108004ec12,
> next = 0x5007eaf000000
> }
>
> crash> x/16i console_drivers
> 0x79009700: lghi %r3,-5
> 0x79009704: aghik %r2,%r1,1164
> 0x7900970a: brasl %r14,0x79386dc8
> 0x79009710: lghi %r1,1
> 0x79009714: laog %r1,%r1,120(%r9)
> 0x7900971a: llgc %r2,5(%r11)
> 0x79009720: llilh %r1,16
> 0x79009724: tmll %r2,1
> 0x79009728: lghi %r2,4096
> 0x7900972c: locgre %r1,%r2
> 0x79009730: lg %r2,160(%r15)
> 0x79009736: llc %r2,142(%r2)
> 0x7900973c: srlg %r1,%r1,0(%r2)
> 0x79009742: clij %r1,1,12,0x7900981e
> 0x79009748: cgij %r8,0,8,0x79009852
> 0x7900974e: la %r2,4(%r8)
>
> crash> sym 0x79009700
> 79009700 (t) iomap_finish_ioend+192
> /usr/src/debug/kernel-5.10.fc33/linux-5.11.0-20210122.rc4.git0.9f29bd8b2e71.300.fc33.s390x/./include/linux/pagemap.h:
> 59
>
> So somehow the pointer for console_drivers changes.
>
> I can't provide the normal kernel crash output as printk is no longer
> working,
I don't understand what you mean here. The crash tool can dump the
printk buffer.
I would be curious to see what the messages look like. It would also be
helpful to know the last message you saw on the console.
> but in crash the backtrace looks like this:
> crash> bt
> PID: 859915 TASK: dad24000 CPU: 9 COMMAND: "ld.so.1"
> LOWCORE INFO:
> -psw : 0x0002000180000000 0x0000000078c8400e
> -function : stop_run at 78c8400e
> -prefix : 0x0041e000
> -cpu timer: 0x7ffff953a957e166
> -clock cmp: 0xd92876863ac66b00
> -general registers:
> 0xf0f0f0f000000000 0x0000000078c8400e
> 0x0000000079984830 0x0000000079984830
> 0x0000000079ac62c0 0x0000000000000002
> 0x0000000000000038 000000000000000000
> 0x000000007a19157e 000000000000000000
> 0x00000000fffffffa 000000000000000000
> 0x00000000dad24000 000000000000000000
> 0x0000000078c8416e 0x00000380033136f0
> -access registers:
> 0x7d5b4da0 0xa2a795c0 0000000000 0000000000
> 0000000000 0000000000 0000000000 0000000000
> 0000000000 0000000000 0000000000 0000000000
> 0000000000 0000000000 0000000000 0000000000
> -control registers:
> 0x00a0000014966a10 0x000000007a15c007
> 0x000000000001d0a0 000000000000000000
> 0x000000000000ffff 0x000000000001d080
> 0x000000003b000000 0x00000001f29b81c7
> 0x0000000000008000 000000000000000000
> 000000000000000000 000000000000000000
> 000000000000000000 0x000000007a15c007
> 0x00000000db000000 0x000000000001d0c0
> -floating point registers:
> 0x5faaaaabeb67f92f 0x0007fffffffffff8
> 0x40400000eb67f000 000000000000000000
> 0x0000000000000007 0x0000006400000000
> 0x000002aa2a63f028 0x000000000963cf85
> 0x000000002a642c60 000000000000000000
> 0x7f85516ceb67f222 0x000003ffeb67f528
> 0x000003ffeb67f230 0x0000000100000000
> 0x000003ffeb67f21d 0x000002aa28d2d970
>
> #0 [38003313710] stop_run at 78c8400e
> #1 [38003313728] atomic_notifier_call_chain at 78ced536
> #2 [38003313778] panic at 7974aeca
> #3 [38003313818] die at 78c897ea
> #4 [38003313880] do_no_context at 78c9b230
> #5 [380033138b8] pgm_check_handler at 7976438c
> PSW: 0404c00180000000 0000000078d304ba (kmsg_dump_rewind+290)
> GPRS: 0000000000000020 0000000000000000 0000000000000000 00000000ffffec88
> 000000000000000e 00000000793f4800 0000000000000224 0000000000000000
> 0000000000000000 0000000000000000 0000000000000224 0005007eaf000000
> 00000000dad24000 0000000000000000 0000038003313a68 0000038003313a18
> #0 [38003313a68] console_unlock at 78d3158e
> #1 [38003313b48] vprintk_emit at 78d32f50
> #2 [38003313ba8] vprintk_default at 78d32f9e
> #3 [38003313c00] printk at 7974bfae
> #4 [38003313c90] show_code at 78c8588e
> #5 [38003313de0] show_registers at 7974a26e
> #6 [38003313e70] show_regs at 78c8961e
> #7 [38003313ea0] pgm_check_handler at 7976438c
> PSW: 0705300080000000 000000007d7983b2 (user space)
> GPRS: 0000000000000000 000000007d798360 0000000000000010 000003ff00000004
> 000000007f854dd0 000000007d7e9788 000003ff00401b30 000000007f854ff8
> 000003ff00000000 000003ff7d5b4da0 000003ff00000000 000003ff00000010
> 000003ff004022c6 000003ff004024b0 0000000080401796 000000007f854de8
>
> kmsg_dump_rewind+290 is:
>
> if (!(con->flags & CON_ENABLED))
> continue;
>
> in kernel/printk/printk.c:1845
>
> I haven't dived into whether our show_code() is doing something wrong
> which was covered in the past or whether that's because of the patch
> above but wanted to make you aware of that in case you have an idea.
> Otherwise i have to dig into the code.
Unless we are dealing with very long printk messages that normally get
truncated (800+ characters) this patch simply adds a string
terminator. I do not see how that could possibly cause this kind of
damage.
When this triggers, there is nothing happening with consoles registering
or deregistering, right?
The string terminator (kernel/printk/printk.c:1402) is only added for
paranoia. If you comment that out, this patch will have no effect (for
"normal" length lines). I would be curious if that somehow makes a
difference for you.
John Ogness
John Ogness <[email protected]> writes:
> On 2021-01-22, Sven Schnelle <[email protected]> wrote:
>>
>> So somehow the pointer for console_drivers changes.
>>
>> I can't provide the normal kernel crash output as printk is no longer
>> working,
>
> I don't understand what you mean here. The crash tool can dump the
> printk buffer.
>
> I would be curious to see what the messages look like. It would also be
> helpful to know the last message you saw on the console.
>
The last message is:
[ 1845.640466] User process fault: interruption code 0007 ilc:2 in libm.so[7d78c000+a3000]
[ 1845.640474] CPU: 9 PID: 859915 Comm: ld.so.1 Not tainted 5.11.0-20210122.rc4.git0.9f29bd8b2e71.300.fc33.s390x+git #1
[ 1845.640476] Hardware name: IBM 8561 T01 703 (LPAR)
[ 1845.640478] User PSW : 0705300080000000 000000007d7983b2
[ 1845.640480] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:1 AS:0 CC:3 PM:0 RI:0 EA:1
[ 1845.640483] User GPRS: 0000000000000000 000000007d798360 0000000000000010 000003ff00000004
[ 1845.640485] 000000007f854dd0 000000007d7e9788 000003ff00401b30 000000007f854ff8
[ 1845.640487] 000003ff00000000 000003ff7d5b4da0 000003ff00000000 000003ff00000010
[ 1845.640489] 000003ff004022c6 000003ff004024b0 0000000080401796 000000007f854de8
That's also what's written to the console. Please note the the output
above is expected. It's only reporting that a user space program
performed an invalid FPU operation. The kernel crash is neither written
to the console nor the dmesg buffer.
>> kmsg_dump_rewind+290 is:
>>
>> if (!(con->flags & CON_ENABLED))
>> continue;
>>
>> in kernel/printk/printk.c:1845
>>
>> I haven't dived into whether our show_code() is doing something wrong
>> which was covered in the past or whether that's because of the patch
>> above but wanted to make you aware of that in case you have an idea.
>> Otherwise i have to dig into the code.
>
> Unless we are dealing with very long printk messages that normally get
> truncated (800+ characters) this patch simply adds a string
> terminator. I do not see how that could possibly cause this kind of
> damage.
>
> When this triggers, there is nothing happening with consoles registering
> or deregistering, right?
That's correct. No registering/unregistering taking place.
> The string terminator (kernel/printk/printk.c:1402) is only added for
> paranoia. If you comment that out, this patch will have no effect (for
> "normal" length lines). I would be curious if that somehow makes a
> difference for you.
I was able to reproduce it in a virtual machine where i have a few more
ways to debug. What i got was:
01: -> 00000000001B8814" MVI 92001000 >> 000000000163F1CD CC 2
That's a watchpoint telling me that the code at 0x1b8814 wants to store
one byte to 0x163f1cd, which is the second byte of console_drivers.
gdb tells me about 0x1b8814:
(gdb) list *(0x1b8814)
0x1b8814 is in record_print_text (/home/svens/ibmgit/linux/kernel/printk/printk.c:1402).
1397 * If a buffer was provided, it will be terminated. Space for the
1398 * string terminator is guaranteed to be available. The terminator is
1399 * not counted in the return value.
1400 */
1401 if (buf_size > 0)
1402 text[len] = 0;
1403
1404 return len;
1405 }
1406
In s390 assembly, this is the store:
0x00000000001b8810 <+0x130>: la %r1,0(%r7,%r9)
0x00000000001b8814 <+0x134>: mvi 0(%r1),0
The cpu registers at the time of write:
01: GRG 0 = 0000000000000020 000000000163F1CD
01: GRG 2 = 0000000000000042 000003E000623A98
01: GRG 4 = 000000000000000E 000000000087BB70
01: GRG 6 = 0000000000000400 *0000000000000224*
01: GRG 8 = 000000000000000F *000000000163EFA9*
01: GRG 10 = 0000000000000033 0000000000000000
01: GRG 12 = 00000000809AE000 000003E000623A98
01: GRG 14 = 00000000001B884C 000003E0006239E8
So r9 is 000000000163EFA9 - seems to be the start of the current message:
0163EFA9: *[ 24.069514] 000000007d7af3c2: b30d0002..debr.%f0,%f2.debr.%f0,%f2
while r7 is the offset, and that one is way to big:
0000000000000224
If you add that to 0163EFA9, you'll see that we're outside of the buffer
and overwriting space after, which is console_drivers.
The message it's trying to print is rather long, so the 0x224 could be
the size of the whole line:
This is not from the same crash, but this is how the message looks like
it's trying to print:
[ 23.960773] User Code: 000000007d7af3ba: 78005000 le %f0,0(%r5)
[ 23.960773] 000000007d7af3be: 78205004 le %f2,4(%r5)
[ 23.960773] #000000007d7af3c2: b30d0002 debr %f0,%f2
[ 23.960773] >000000007d7af3c6: a7280000 lhi %r2,0
[ 23.960773] 000000007d7af3ca: 07fe bcr 15,%r14
[ 23.960773] 000000007d7af3cc: 0707 bcr 0,%r7
[ 23.960773] 000000007d7af3ce: 0707 bcr 0,%r7
[ 23.960773] 000000007d7af3d0: c050000289ec larl %r5,000000007d8007a8
I'm pretty sure it's related to the way how the s390 disassembler
prints the buffer, it uses several pr_cont() calls, and it's crashing in the
last pr_cont("\n") (in arch/s390/kernel/dis.c - show_code());
I'm trying to get the content of the log buffer and other state, if
there's anything else i can provide let me know.
Sven Schnelle <[email protected]> writes:
> John Ogness <[email protected]> writes:
>
>> On 2021-01-22, Sven Schnelle <[email protected]> wrote:
> I was able to reproduce it in a virtual machine where i have a few more
> ways to debug. What i got was:
>
> 01: -> 00000000001B8814" MVI 92001000 >> 000000000163F1CD CC 2
>
> That's a watchpoint telling me that the code at 0x1b8814 wants to store
> one byte to 0x163f1cd, which is the second byte of console_drivers.
>
> gdb tells me about 0x1b8814:
>
> (gdb) list *(0x1b8814)
> 0x1b8814 is in record_print_text (/home/svens/ibmgit/linux/kernel/printk/printk.c:1402).
> 1397 * If a buffer was provided, it will be terminated. Space for the
> 1398 * string terminator is guaranteed to be available. The terminator is
> 1399 * not counted in the return value.
> 1400 */
> 1401 if (buf_size > 0)
> 1402 text[len] = 0;
I don't think i have really understood how all the printk magic works,
but using r->text_buf[len] seems to be the correct place to put the zero byte
in that case?
> 1403
> 1404 return len;
> 1405 }
> 1406
>
Hi Sven,
Thanks for the outstanding analysis!
On 2021-01-23, Sven Schnelle <[email protected]> wrote:
>> 1401 if (buf_size > 0)
>> 1402 text[len] = 0;
>
> I don't think i have really understood how all the printk magic works,
> but using r->text_buf[len] seems to be the correct place to put the
> zero byte in that case?
Yes, you are correct! @text is pointing to the beginning of the
currently processed line, not the beginning of the buffer.
I will submit a patch to fix our recent fix (unless you would like to do
that).
Thank you for all your help with this!
John Ogness
John Ogness <[email protected]> writes:
> Hi Sven,
>
> Thanks for the outstanding analysis!
>
> On 2021-01-23, Sven Schnelle <[email protected]> wrote:
>>> 1401 if (buf_size > 0)
>>> 1402 text[len] = 0;
>>
>> I don't think i have really understood how all the printk magic works,
>> but using r->text_buf[len] seems to be the correct place to put the
>> zero byte in that case?
>
> Yes, you are correct! @text is pointing to the beginning of the
> currently processed line, not the beginning of the buffer.
>
> I will submit a patch to fix our recent fix (unless you would like to do
> that).
Please go ahead, thank you!
On Thu, Jan 14, 2021 at 06:10:12PM +0106, John Ogness wrote:
> Before commit b6cf8b3f3312 ("printk: add lockless ringbuffer"),
> msg_print_text() would only write up to size-1 bytes into the
> provided buffer. Some callers expect this behavior and append
> a terminator to returned string. In particular:
>
> arch/powerpc/xmon/xmon.c:dump_log_buf()
> arch/um/kernel/kmsg_dump.c:kmsg_dumper_stdout()
>
> msg_print_text() has been replaced by record_print_text(), which
> currently fills the full size of the buffer. This causes a
> buffer overflow for the above callers.
>
> Change record_print_text() so that it will only use size-1 bytes
> for text data. Also, for paranoia sakes, add a terminator after
> the text data.
>
> And finally, document this behavior so that it is clear that only
> size-1 bytes are used and a terminator is added.
Hi John,
I am seeing KASAN reporting incorrect 1-byte access in exactly
same location Sven has identified before. In case there no
fix for it yet, please see below what happens in case of pretty
large buffer - WARN_ONCE() invocation in my case.
>
> Fixes: b6cf8b3f3312 ("printk: add lockless ringbuffer")
> Signed-off-by: John Ogness <[email protected]>
> ---
> kernel/printk/printk.c | 35 +++++++++++++++++++++++++++--------
> 1 file changed, 27 insertions(+), 8 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ffdd0dc7ec6d..73f9eae19f05 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1293,9 +1293,15 @@ static size_t info_print_prefix(const struct printk_info *info, bool syslog,
> * - Add prefix for each line.
> * - Add the trailing newline that has been removed in vprintk_store().
> * - Drop truncated lines that do not longer fit into the buffer.
> + * - Add a trailing newline.
> + * - Add a string terminator.
> + *
> + * Since the produced string is always terminated, the maximum possible
> + * return value is @r->text_buf_size - 1;
> *
> * Return: The length of the updated/prepared text, including the added
> - * prefixes and the newline. The dropped line(s) are not counted.
> + * prefixes and the newline. The terminator is not counted. The dropped
> + * line(s) are not counted.
> */
> static size_t record_print_text(struct printk_record *r, bool syslog,
> bool time)
> @@ -1338,26 +1344,31 @@ static size_t record_print_text(struct printk_record *r, bool syslog,
>
> /*
> * Truncate the text if there is not enough space to add the
> - * prefix and a trailing newline.
> + * prefix and a trailing newline and a terminator.
> */
> - if (len + prefix_len + text_len + 1 > buf_size) {
> + if (len + prefix_len + text_len + 1 + 1 > buf_size) {
> /* Drop even the current line if no space. */
> - if (len + prefix_len + line_len + 1 > buf_size)
> + if (len + prefix_len + line_len + 1 + 1 > buf_size)
> break;
>
> - text_len = buf_size - len - prefix_len - 1;
> + text_len = buf_size - len - prefix_len - 1 - 1;
> truncated = true;
> }
>
> memmove(text + prefix_len, text, text_len);
> memcpy(text, prefix, prefix_len);
>
> + /*
> + * Increment the prepared length to include the text and
> + * prefix that were just moved+copied. Also increment for the
> + * newline at the end of this line. If this is the last line,
> + * there is no newline, but it will be added immediately below.
> + */
> len += prefix_len + line_len + 1;
(1) the next iteration of would-be-length stored in len
> -
> if (text_len == line_len) {
(2) but the buffer is processed, so we get here
> /*
> - * Add the trailing newline removed in
> - * vprintk_store().
> + * This is the last line. Add the trailing newline
> + * removed in vprintk_store().
> */
> text[prefix_len + line_len] = '\n';
> break;
(3) and bail out from the loop
> @@ -1382,6 +1393,14 @@ static size_t record_print_text(struct printk_record *r, bool syslog,
> text_len -= line_len + 1;
> }
>
> + /*
> + * If a buffer was provided, it will be terminated. Space for the
> + * string terminator is guaranteed to be available. The terminator is
> + * not counted in the return value.
> + */
> + if (buf_size > 0)
> + text[len] = 0;
(4) trying to terminate, but len is beyond the buffer
BUG: KASAN: global-out-of-bounds in record_print_text+0x1d4/0x248
Write of size 1 at addr 00000000bf9e6992 by task swapper/0/1
Reverting the patch shuts the complain.
> +
> return len;
> }
>
> --
> 2.20.1
>
On 2021-02-26, Alexander Gordeev <[email protected]> wrote:
> I am seeing KASAN reporting incorrect 1-byte access in exactly
> same location Sven has identified before. In case there no
> fix for it yet, please see below what happens in case of pretty
> large buffer - WARN_ONCE() invocation in my case.
It looks like you have not applied the fix yet:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=08d60e5999540110576e7c1346d486220751b7f9
John Ogness