printk: Fix incorrect length from print_time() when seconds > 99999
PATCH 1/1 printk: Fix incorrect length from print_time() when seconds > 99999
From: Roland Dreier <[email protected]>
print_prefix() passes a NULL buf to print_time() to get the length of the time prefix; when printk times are enabled, the current code just returns the constant 15, which matches the format "[%5lu.%06lu] " used to print the time value. However, this is obviously incorrect when the whole seconds part of the time gets beyond 5 digits (100000 seconds is a bit more than a day of uptime).
The simple fix is to use snprintf(NULL, 0, ...) to calculate the actual length of the time prefix. This could be micro-optimized but it seems better to have simpler, more readable code here.
The bug leads to the syslog system call miscomputing which messages fit into the userspace buffer. If there are enough messages to fill log_buf_len and some have a timestamp >= 100000, dmesg may fail with:
# dmesg
klogctl: Bad addressWhen this happens, strace shows that the failure is indeed EFAULT due to the kernel mistakenly accessing past the end of dmesg's buffer, since dmesg asks the kernel how big a buffer it needs, allocates a bit more, and then gets an error when it asks the kernel to fill it:
syslog(0xa, 0, 0) = 1048576
mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa4d25d2000
syslog(0x3, 0x7fa4d25d2010, 0x100008) = -1 EFAULT (Bad address)--- kernel/printk.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-)
kernel/printk.c +3 -2
@@ -870,10 +870,11 @@ static size_t print_time(u64 ts, char *buf)if (!printk_time)return 0 ; + rem_nsec =do_div (ts,1000000000 ); +if (!buf) -return 15 ; +return snprintf (NULL ,0 ,"[%5lu.000000] " , (unsigned long )ts); - rem_nsec =do_div (ts,1000000000 );return sprintf (buf,"[%5lu.%06lu] " , (unsigned long )ts, rem_nsec /1000 ); }
Signature · 1 line
1.8.0
Quoted 25 lines · Roland Dreier
From: Roland Dreier <[email protected]>
print_prefix()passes a NULL buf toprint_time()to get the length of the time prefix; when printk times are enabled, the current code just returns the constant 15, which matches the format "[%5lu.%06lu] " used to print the time value. However, this is obviously incorrect when the whole seconds part of the time gets beyond 5 digits (100000 seconds is a bit more than a day of uptime).The simple fix is to use
snprintf(NULL, 0, ...)to calculate the actual length of the time prefix. This could be micro-optimized but it seems better to have simpler, more readable code here.The bug leads to the syslog system call miscomputing which messages fit into the userspace buffer. If there are enough messages to fill
log_buf_lenand some have a timestamp >= 100000, dmesg may fail with:# dmesg klogctl: Bad addressWhen this happens, strace shows that the failure is indeed EFAULT due to the kernel mistakenly accessing past the end of dmesg's buffer, since dmesg asks the kernel how big a buffer it needs, allocates a bit more, and then gets an error when it asks the kernel to fill it:
Quoted 5 lines
syslog(0xa, 0, 0) = 1048576 mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa4d25d2000 syslog(0x3, 0x7fa4d25d2010, 0x100008) = -1 EFAULT (Bad address)Signed-off-by Roland Dreier <[email protected]>
Nice work. When did you start seeing this problem, 3.6 or so? I ask as it's probably something that should go to stable as well if so.
Andrew seems to be keeping the printk patches these days, so I'll let him pick this up with:
Quoted 30 lines · Greg Kroah-Hartman
Quoted 29 lines · Roland Dreier
From: Roland Dreier <[email protected]>
print_prefix()passes a NULL buf toprint_time()to get the length of the time prefix; when printk times are enabled, the current code just returns the constant 15, which matches the format "[%5lu.%06lu] " used to print the time value. However, this is obviously incorrect when the whole seconds part of the time gets beyond 5 digits (100000 seconds is a bit more than a day of uptime).The simple fix is to use
snprintf(NULL, 0, ...)to calculate the actual length of the time prefix. This could be micro-optimized but it seems better to have simpler, more readable code here.The bug leads to the syslog system call miscomputing which messages fit into the userspace buffer. If there are enough messages to fill
log_buf_lenand some have a timestamp >= 100000, dmesg may fail with:# dmesg klogctl: Bad addressWhen this happens, strace shows that the failure is indeed EFAULT due to the kernel mistakenly accessing past the end of dmesg's buffer, since dmesg asks the kernel how big a buffer it needs, allocates a bit more, and then gets an error when it asks the kernel to fill it:
syslog(0xa, 0, 0) = 1048576 mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa4d25d2000 syslog(0x3, 0x7fa4d25d2010, 0x100008) = -1 EFAULT (Bad address)
Quoted 7 lines
Quoted 1 line
Signed-off-by Roland Dreier <[email protected]>Nice work. When did you start seeing this problem, 3.6 or so? I ask as it's probably something that should go to stable as well if so.
Andrew seems to be keeping the printk patches these days, so I'll let him pick this up with:
Sylvan Munaut did something similar
https://lkml.org/lkml/2012/12/5/168
It's been around quite awhile.
Quoted 2 lines · Joe Perches
Sylvan Munaut did something similar
https://lkml.org/lkml/2012/12/5/168
Missed that and duplicated the debugging :(
Sorry Sylvain.
I guess my patch may be preferable, since I happened to use the snprintf() method that you suggest -- all the open-coded digit-counting seems a bit verbose and perhaps hard to read and see the equivalence to the sprintf.
But certainly Sylvain fixed this quite a bit earlier and he should get credit.
- R.
Quoted 10 lines · Roland Dreier
Quoted 2 lines · Joe Perches
Sylvan Munaut did something similar
https://lkml.org/lkml/2012/12/5/168Missed that and duplicated the debugging :(
Sorry Sylvain.I guess my patch may be preferable, since I happened to use the
snprintf()method that you suggest -- all the open-coded digit-counting seems a bit verbose and perhaps hard to read and see the equivalence to the sprintf.
the kernel implementation of snprint/vsnprintf does expand on c99 and allow snprintf(NULL, 0... so your code should work fine.
I think the
snprintf(NULL, 0
might be suspect.
(the same form is already used in drivers/usb/gadget/composite.c)
man snprintf says in part:
Concerning the return value of snprintf(), SUSv2 and C99 contradict each other: when snprintf() is called with size=0 then SUSv2 stipulates an unspecified return value less than 1, while C99 allows str to be NULL in this case, and gives the return value (as always) as the number of characters that would have been written in case the output string has been large enough.
If not here, maybe the tools/perf/util/values.c code that uses the same form might need changing.
Hi,
Quoted 5 lines
Quoted 2 lines
Sylvan Munaut did something similar
https://lkml.org/lkml/2012/12/5/168Missed that and duplicated the debugging :(
Sorry Sylvain.
I should have followed up on the patch sooner, but I basically finished testing it fixed all the issues and posted it just before leaving for vacation and I just got back (and didn't check my work email there).
Quoted 3 lines
I guess my patch may be preferable, since I happened to use the
snprintf()method that you suggest -- all the open-coded digit-counting seems a bit verbose and perhaps hard to read and see the equivalence to the sprintf.
Yes, I just did it that way to match the way if was done in other parts of that file in ... the snprintf method is clearly more readable.
Cheers,
Sylvain
Quoted 2 lines · Greg Kroah-Hartman
Nice work. When did you start seeing this problem, 3.6 or so? I ask as it's probably something that should go to stable as well if so.
We happened to see it when we rebased to the 3.6 kernel, but as far as I can see, the bug has been there as long as print_time(), which comes from 084681d14e42 ("printk: flush continuation lines immediately to console") in 3.5-rc5. When I was doing a web search for info on the problem, I found at least the following reports:
https://bbs.archlinux.org/viewtopic.php?id=148100
https://lkml.org/lkml/2012/10/17/81
so yeah this seems to be stable material.
Quoted 4 lines
Andrew seems to be keeping the printk patches these days, so I'll let him pick this up with:
Signed-off-by Greg Kroah-Hartman <[email protected]>