[PATCH 0/1] another size-1 fixup from msg_print_text()

[PATCH 0/1] another size-1 fixup from msg_print_text()

[John Ogness]

Hello,

I think this is the last fixup from the msg_print_text() size-1
quirk that has been hiding in the kernel for nearly 8 years.

This is a very simple fix for an obvious problem, so my commit
message may be way too large. There probably is not a need to
prove the error. Trim/edit the commit message as you feel fit.

This change as a separate commit is important because I will be
to posting a series that consolidates this code and I don't want
my consolidation secretly fixing such long-standing issues.

John Ogness (1):
  printk: fix syslog_print_all() 1024-byte edge case

 kernel/printk/printk.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

-- 
2.20.1

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

[John Ogness]

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@linutronix.de>
---
 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

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

[John Ogness]

On 2021-01-20, John Ogness <john.ogness@linutronix.de> wrote:
> 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.

Sorry, please disregard this patch. The problem is not because of the
size-1 behavior of record_print_text(). It is because syslog_print_all()
is allocating a temp buffer that is not large enough to hold multi-line
syslog-expanded records.

That problem can be solved another day, if we even want to consider it a
problem.

Sorry for the noise.

John Ogness