[PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Roland Dreier]

From: Roland Dreier <roland@purestorage.com>

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 address

When 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)

Signed-off-by: Roland Dreier <roland@purestorage.com>
---
 kernel/printk.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 19c0d7b..357f714 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -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);
 }
-- 
1.8.0

Re: [PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Greg Kroah-Hartman]

On Fri, Dec 28, 2012 at 08:23:04PM -0800, Roland Dreier wrote:
> From: Roland Dreier <roland@purestorage.com>
> 
> 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 address
> 
> When 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)
> 
> Signed-off-by: Roland Dreier <roland@purestorage.com>

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:

Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

Re: [PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Joe Perches]

On Sat, 2012-12-29 at 09:56 -0800, Greg Kroah-Hartman wrote:
> On Fri, Dec 28, 2012 at 08:23:04PM -0800, Roland Dreier wrote:
> > From: Roland Dreier <roland@purestorage.com>
> > 
> > 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 address
> > 
> > When 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)
> > 
> > Signed-off-by: Roland Dreier <roland@purestorage.com>
> 
> 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.

Re: [PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Roland Dreier]

On Sat, Dec 29, 2012 at 9:56 AM, Greg Kroah-Hartman
<gregkh@linuxfoundation.org> wrote:
> 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.

> 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 <gregkh@linuxfoundation.org>

Re: [PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Roland Dreier]

On Sat, Dec 29, 2012 at 12:08 PM, Joe Perches <joe@perches.com> wrote:
> 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.

Re: [PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Joe Perches]

On Sat, 2012-12-29 at 14:27 -0800, Roland Dreier wrote:
> On Sat, Dec 29, 2012 at 12:08 PM, Joe Perches <joe@perches.com> wrote:
> > 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.

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.

Re: [PATCH] printk: Fix incorrect length from print_time() when seconds > 99999

[Sylvain Munaut]

Hi,

>> Sylvan Munaut did something similar
>> https://lkml.org/lkml/2012/12/5/168
>
> Missed 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).


> 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