Wrong length / buffer overlow by the syslog syscall

Wrong length / buffer overlow by the syslog syscall

[Sylvain Munaut]

Hi,

I was debugging a segfault in the 'dmesg' utility that I finally
traced to the syslog syscall overflowing the buffer.
I'm under a 3.6.8 kernel and it has commit
e3756477aec028427fec767957c0d4b6cfb87208 present which apparently
fixed a similar issue, but I still have some occurence.

strace dmesg -s 8192

shows:

syslog(0x3, 0xb4e060, 0x2008)           = 8259

so despite being given a buffer of 8200 bytes, it writes 8259 ...

It happens on several machines and this only seem to happen if there
was a wrap around in the log buffer (it's a first observation on a
limited number of sample so it might be a coincidence)


Cheers,

    Sylvain

PS: Please cc me in any response, I'm not on the list.

Re: Wrong length / buffer overlow by the syslog syscall

[Sylvain Munaut]

Hi,

> It happens on several machines and this only seem to happen if there
> was a wrap around in the log buffer (it's a first observation on a
> limited number of sample so it might be a coincidence)

I think the culprit is print_time and has nothing to do with wrap
around, just the uptime.

static size_t print_time(u64 ts, char *buf)
{
       unsigned long rem_nsec;

       if (!printk_time)
               return 0;

       if (!buf)
               return 15;

       rem_nsec = do_div(ts, 1000000000);
       return sprintf(buf, "[%5lu.%06lu] ",
                      (unsigned long)ts, rem_nsec / 1000);
}

it assumes the time will always be 15 char which is wrong. The %5lu
only guarantees a _minimum_ length of 5 chars, but if ts is large
enough it can be 6,7,...
and indeed in my logs I see "[601678.426219] "  which is 16 chars
(includes the space at the end).

Cheers,

     Sylvain

[RFC] printk: Fix print_time length computation when no buffer is given

[Sylvain Munaut]

The "%5lu" part of the sprintf only guarantees a minimum length,
not a maximum one. This patch should make it correct for any
possible timestamp.

Signed-off-by: Sylvain Munaut <s.munaut@whatever-company.com>
---
 kernel/printk.c |   13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 66a2ea3..2ceceea 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -847,8 +847,17 @@ static size_t print_time(u64 ts, char *buf)
 	if (!printk_time)
 		return 0;
 
-	if (!buf)
-		return 15;
+	if (!buf) {
+		size_t len = 15;
+		u64 ts_limit = (u64)100000 * (u64)1000000000;
+
+		while ((ts > ts_limit) && (len < 21)) {
+			len++;
+			ts_limit = 10 * ts_limit;
+		}
+
+		return len;
+	}
 
 	rem_nsec = do_div(ts, 1000000000);
 	return sprintf(buf, "[%5lu.%06lu] ",
-- 
1.7.10.4

[PATCH] printk: Fix print_time length computation when no buffer is given

[Sylvain Munaut]

The "%5lu" part of the sprintf only guarantees a minimum length,
not a maximum one. This patch should make it correct for any
possible timestamp.

This problem dates back from the printk conversion to records AFAICT.

I've tested this locally both by verifying 'dmesg' no longer
segfaulted and also by checking that before this patch the
buffer was overrun by exactly the number of char corresponding to
extra digits in the timestamps.

Cc: Kay Sievers <kay@vrfy.org>
Cc: stable@kernel.org
Signed-off-by: Sylvain Munaut <s.munaut@whatever-company.com>
---
 kernel/printk.c |   13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 66a2ea3..2ceceea 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -847,8 +847,17 @@ static size_t print_time(u64 ts, char *buf)
 	if (!printk_time)
 		return 0;
 
-	if (!buf)
-		return 15;
+	if (!buf) {
+		size_t len = 15;
+		u64 ts_limit = (u64)100000 * (u64)1000000000;
+
+		while ((ts > ts_limit) && (len < 21)) {
+			len++;
+			ts_limit = 10 * ts_limit;
+		}
+
+		return len;
+	}
 
 	rem_nsec = do_div(ts, 1000000000);
 	return sprintf(buf, "[%5lu.%06lu] ",
-- 
1.7.10.4

Re: [PATCH] printk: Fix print_time length computation when no buffer is given

[Joe Perches]

On Thu, 2012-12-06 at 18:09 +0100, Sylvain Munaut wrote:
> The "%5lu" part of the sprintf only guarantees a minimum length,
> not a maximum one. This patch should make it correct for any
> possible timestamp.
> 
> This problem dates back from the printk conversion to records AFAICT.
> 
> I've tested this locally both by verifying 'dmesg' no longer
> segfaulted and also by checking that before this patch the
> buffer was overrun by exactly the number of char corresponding to
> extra digits in the timestamps.
> 
> Cc: Kay Sievers <kay@vrfy.org>
> Cc: stable@kernel.org
> Signed-off-by: Sylvain Munaut <s.munaut@whatever-company.com>
> ---
>  kernel/printk.c |   13 +++++++++++--
>  1 file changed, 11 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 66a2ea3..2ceceea 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -847,8 +847,17 @@ static size_t print_time(u64 ts, char *buf)
>  	if (!printk_time)
>  		return 0;
>  
> -	if (!buf)
> -		return 15;
> +	if (!buf) {
> +		size_t len = 15;
> +		u64 ts_limit = (u64)100000 * (u64)1000000000;
> +
> +		while ((ts > ts_limit) && (len < 21)) {
> +			len++;
> +			ts_limit = 10 * ts_limit;
> +		}

Perhaps use snprintf for sizing something like below?
(untested/uncompiled)

static size_t print_time(u64 ts, char *buf)
{
	unsigned long rem_nsec;
	char *tmpbuf = buf;
	int size = 15;			/* expected size of non-null buf */
	char local_buf[1];

	if (!printk_time)
		return 0;

	if (!buf) {			/* emit to a dummy buf instead */
		tmpbuf = local_buf;
		size = sizeof(local_buf);
	}
	
	rem_nsec = do_div(ts, 1000000000);

	return snprintf(tmpbuf, size, "[%5lu.%06lu] ",
			(unsigned long)ts, rem_nsec / 1000);
}

It's perhaps unfortunate that print_time doesn't take a
a buffer and a size_t of buffer.