[PATCH 1/1] printk: fix syslog_print_all() 1024-byte edge case

From: John Ogness
Date: Wed Jan 20 2021 - 14:48:39 EST


If klogctl(SYSLOG_ACTION_READ_ALL) is called with a buffer size
of 1024 and the message data will exactly fill 1024 bytes and the
last message of that is multi-line, the last line of the last
message will be silently dropped.

This is because syslog_print_all() is assuming record_print_text()
will fill @size bytes and chooses the first record on this basis.
But since record_print_text() only fills @size-1 bytes, it will
truncate the last message. This behavior exists since the
introduction of msg_print_text() in commit 3ce9a7c0ac28 ("printk() -
restore prefix/timestamp printing for multi-newline strings").

SYSLOG_ACTION_READ_ALL is only supposed to print full messages, so
the expected behavior would be to drop the full multi-line message.
Fix this edge case by changing syslog_print_all() to correctly
choose the first message with the knowledge that
record_print_text() will only fill up to @size-1 bytes.

To test the syslog interface, a simple "kmsg" tool was written to
call klogctl() based on provided parameters. The tool prints the
syslog data it read and the size returned by klogctl().

A wrapper script was used to generate a single multi-line test
message and run kmsg.

----- BEGIN syslog-1024-test.sh -----
#!/bin/sh

msg=""
for i in `seq $1`; do msg="$msg."; done
msg="$msg\nhello1"
msg="$msg\nhello2"

dmesg -c > /dev/null
echo -e "$msg" > /dev/kmsg
./kmsg SYSLOG_ACTION_READ_ALL 1024
----- END syslog-1024-test.sh -----

When $1 is 928, the syslog data will be 1024 bytes and trigger the
edge case (assuming early timestamps and CALLER_ID enabled).

BEFORE this commit:

# ./syslog-1024-test.sh 927
kmsg: klogctl(SYSLOG_ACTION_READ_ALL) with buffer of 1024 bytes
<12>[ 115.933677][ T1138] ................
<12>[ 115.933677][ T1138] hello1
<12>[ 115.933677][ T1138] hello2
read 1023 bytes from klogctl

# ./syslog-1024-test.sh 928
kmsg: klogctl(SYSLOG_ACTION_READ_ALL) with buffer of 1024 bytes
<12>[ 124.834804][ T1143] ................
<12>[ 124.834804][ T1143] hello1
read 990 bytes from klogctl

# ./syslog-1024-test.sh 929
kmsg: klogctl(SYSLOG_ACTION_READ_ALL) with buffer of 1024 bytes
read 0 bytes from klogctl

AFTER this commit:

# ./syslog-1024-test.sh 927
kmsg: klogctl(SYSLOG_ACTION_READ_ALL) with buffer of 1024 bytes
<12>[ 43.079094][ T1096] ................
<12>[ 43.079094][ T1096] hello1
<12>[ 43.079094][ T1096] hello2
read 1023 bytes from klogctl

# ./syslog-1024-test.sh 928
kmsg: klogctl(SYSLOG_ACTION_READ_ALL) with buffer of 1024 bytes
read 0 bytes from klogctl

# ./syslog-1024-test.sh 929
kmsg: klogctl(SYSLOG_ACTION_READ_ALL) with buffer of 1024 bytes
read 0 bytes from klogctl

Fixes: 3ce9a7c0ac28 ("printk() - restore prefix/timestamp printing for multi-newline strings")
Signed-off-by: John Ogness <john.ogness@xxxxxxxxxxxxx>
---
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 6639a0cfe0ac..b640d34e0351 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1513,7 +1513,7 @@ static int syslog_print_all(char __user *buf, int size, bool clear)

/* move first record forward until length fits into the buffer */
prb_for_each_info(clear_seq, prb, seq, &info, &line_count) {
- if (len <= size)
+ if (len < size)
break;
len -= get_record_print_text_size(&info, line_count, true, time);
}
--
2.20.1