[patch] tracing: off by one in __trace_array_vprintk()

[patch] tracing: off by one in __trace_array_vprintk()

[Dan Carpenter]

This check says "goto out;" if we had to truncate the string.

The "tbuffer" buffer has TRACE_BUF_SIZE bytes.  The vsnprintf() function
returns the number of characters (not counting the NUL char) which would
have been printed if there were space.  If we we tried to print
TRACE_BUF_SIZE characters, the last character would have been truncated
to make space for the NUL character so we should "goto out;".

My other concern here was that a few lines later we do:

	entry->buf[len] = '\0';

I worried that maybe we were putting the NUL char past the end of the
array but I wasn't smart enough to figure out the size of entry->buf[].

Signed-off-by: Dan Carpenter <dan.carpenter@oracle.com>

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 42a822d..22af2ae 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2161,7 +2161,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 	}
 
 	len = vsnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
-	if (len > TRACE_BUF_SIZE)
+	if (len >= TRACE_BUF_SIZE)
 		goto out;
 
 	local_save_flags(flags);

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Steven Rostedt]

On Wed, 26 Nov 2014 17:06:21 +0300
Dan Carpenter <dan.carpenter@oracle.com> wrote:

> This check says "goto out;" if we had to truncate the string.
> 
> The "tbuffer" buffer has TRACE_BUF_SIZE bytes.  The vsnprintf() function
> returns the number of characters (not counting the NUL char) which would
> have been printed if there were space.  If we we tried to print
> TRACE_BUF_SIZE characters, the last character would have been truncated
> to make space for the NUL character so we should "goto out;".
> 
> My other concern here was that a few lines later we do:
> 
> 	entry->buf[len] = '\0';
> 
> I worried that maybe we were putting the NUL char past the end of the
> array but I wasn't smart enough to figure out the size of entry->buf[].

entry is of type struct print_entry *, which is defined by macro magic
(sorry), and would look like this:

struct print_entry {
	unsigned long		ip;
	char			buf[];
};

But then it is allocated like so:

	size = sizeof(*entry) + len + 1;
	event = trace_buffer_lock_reserve(buffer, TRACE_PRINT, size,
					  flags, pc);

	entry = ring_buffer_event_data(event);

Now that size is the key. The "len + 1" covers the string. Which means

	entry->buf[len] = '\0';

is fine.

-- Steve


> 
> Signed-off-by: Dan Carpenter <dan.carpenter@oracle.com>
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 42a822d..22af2ae 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -2161,7 +2161,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
>  	}
>  
>  	len = vsnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
> -	if (len > TRACE_BUF_SIZE)
> +	if (len >= TRACE_BUF_SIZE)
>  		goto out;
>  
>  	local_save_flags(flags);

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Dan Carpenter]

On Wed, Nov 26, 2014 at 09:25:37AM -0500, Steven Rostedt wrote:
> On Wed, 26 Nov 2014 17:06:21 +0300
> Dan Carpenter <dan.carpenter@oracle.com> wrote:
> 
> > This check says "goto out;" if we had to truncate the string.
> > 
> > The "tbuffer" buffer has TRACE_BUF_SIZE bytes.  The vsnprintf() function
> > returns the number of characters (not counting the NUL char) which would
> > have been printed if there were space.  If we we tried to print
> > TRACE_BUF_SIZE characters, the last character would have been truncated
> > to make space for the NUL character so we should "goto out;".
> > 
> > My other concern here was that a few lines later we do:
> > 
> > 	entry->buf[len] = '\0';
> > 
> > I worried that maybe we were putting the NUL char past the end of the
> > array but I wasn't smart enough to figure out the size of entry->buf[].
> 
> entry is of type struct print_entry *, which is defined by macro magic
> (sorry),

I figure this bit out using make devel/kernel/trace/trace.i.

> and would look like this:
> 
> struct print_entry {
> 	unsigned long		ip;
> 	char			buf[];
> };
> 
> But then it is allocated like so:
> 
> 	size = sizeof(*entry) + len + 1;
> 	event = trace_buffer_lock_reserve(buffer, TRACE_PRINT, size,
> 					  flags, pc);
> 
> 	entry = ring_buffer_event_data(event);

I was so close to figuring this out on my own...  Let me send a v2 with
an amended changelog.

regards,
dan carpenter

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Steven Rostedt]

On Wed, 26 Nov 2014 17:06:21 +0300
Dan Carpenter <dan.carpenter@oracle.com> wrote:

> This check says "goto out;" if we had to truncate the string.
> 
> The "tbuffer" buffer has TRACE_BUF_SIZE bytes.  The vsnprintf() function
> returns the number of characters (not counting the NUL char) which would
> have been printed if there were space.  If we we tried to print
> TRACE_BUF_SIZE characters, the last character would have been truncated
> to make space for the NUL character so we should "goto out;".
> 

Oh, and the NUL character is never copied. We copy the string into the
buffer with:

	memcpy(&entry->buf, tbuffer, len);

Where len does not include NUL, and why we add it ourselves.

-- Steve

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Dan Carpenter]

On Wed, Nov 26, 2014 at 09:27:06AM -0500, Steven Rostedt wrote:
> On Wed, 26 Nov 2014 17:06:21 +0300
> Dan Carpenter <dan.carpenter@oracle.com> wrote:
> 
> > This check says "goto out;" if we had to truncate the string.
> > 
> > The "tbuffer" buffer has TRACE_BUF_SIZE bytes.  The vsnprintf() function
> > returns the number of characters (not counting the NUL char) which would
> > have been printed if there were space.  If we we tried to print
> > TRACE_BUF_SIZE characters, the last character would have been truncated
> > to make space for the NUL character so we should "goto out;".
> > 
> 
> Oh, and the NUL character is never copied. We copy the string into the
> buffer with:
> 
> 	memcpy(&entry->buf, tbuffer, len);
> 
> Where len does not include NUL, and why we add it ourselves.

Yeah.  I noticed that.  Probably we should change the memcpy() to:

	memcpy(&entry->buf, tbuffer, len + 1);

and remove separate NUL assignment?  It's a speedup!  I'll do it in v2.

regards,
dan carpenter

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Steven Rostedt]

On Wed, 26 Nov 2014 17:37:19 +0300
Dan Carpenter <dan.carpenter@oracle.com> wrote:

> On Wed, Nov 26, 2014 at 09:27:06AM -0500, Steven Rostedt wrote:
> > On Wed, 26 Nov 2014 17:06:21 +0300
> > Dan Carpenter <dan.carpenter@oracle.com> wrote:
> > 
> > > This check says "goto out;" if we had to truncate the string.
> > > 
> > > The "tbuffer" buffer has TRACE_BUF_SIZE bytes.  The vsnprintf() function
> > > returns the number of characters (not counting the NUL char) which would
> > > have been printed if there were space.  If we we tried to print
> > > TRACE_BUF_SIZE characters, the last character would have been truncated
> > > to make space for the NUL character so we should "goto out;".
> > > 
> > 
> > Oh, and the NUL character is never copied. We copy the string into the
> > buffer with:
> > 
> > 	memcpy(&entry->buf, tbuffer, len);
> > 
> > Where len does not include NUL, and why we add it ourselves.
> 
> Yeah.  I noticed that.  Probably we should change the memcpy() to:
> 
> 	memcpy(&entry->buf, tbuffer, len + 1);
> 
> and remove separate NUL assignment?  It's a speedup!  I'll do it in v2.
> 

I highly doubt it's much of a speed up. And we do that by sacrificing
that one byte of buffer, which would lose the printk if len does equal
TRACE_BUF_SIZE.

I don't see a bug here. What exactly are you trying to fix?

-- Steve

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Dan Carpenter]

On Wed, Nov 26, 2014 at 09:43:06AM -0500, Steven Rostedt wrote:
> I highly doubt it's much of a speed up. And we do that by sacrificing
> that one byte of buffer, which would lose the printk if len does equal
> TRACE_BUF_SIZE.
> 
> I don't see a bug here. What exactly are you trying to fix?

Heh.  vsnprintf() is going to put a NUL char at the end of the string
even if you don't plan to use it.  :P

Another option would be to just print truncated output.  We could use
vscnprintf() and remove the off by one limit check.

regards,
dan carpenter

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 42a822d..ab76b7b 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2160,9 +2160,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 		goto out;
 	}
 
-	len = vsnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
-	if (len > TRACE_BUF_SIZE)
-		goto out;
+	len = vscnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
 
 	local_save_flags(flags);
 	size = sizeof(*entry) + len + 1;
@@ -2173,8 +2171,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 	entry = ring_buffer_event_data(event);
 	entry->ip = ip;
 
-	memcpy(&entry->buf, tbuffer, len);
-	entry->buf[len] = '\0';
+	memcpy(&entry->buf, tbuffer, len + 1);
 	if (!call_filter_check_discard(call, entry, buffer, event)) {
 		__buffer_unlock_commit(buffer, event);
 		ftrace_trace_stack(buffer, flags, 6, pc);

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Steven Rostedt]

On Wed, 26 Nov 2014 18:05:41 +0300
Dan Carpenter <dan.carpenter@oracle.com> wrote:

> On Wed, Nov 26, 2014 at 09:43:06AM -0500, Steven Rostedt wrote:
> > I highly doubt it's much of a speed up. And we do that by sacrificing
> > that one byte of buffer, which would lose the printk if len does equal
> > TRACE_BUF_SIZE.
> > 
> > I don't see a bug here. What exactly are you trying to fix?
> 
> Heh.  vsnprintf() is going to put a NUL char at the end of the string
> even if you don't plan to use it.  :P
> 
> Another option would be to just print truncated output.  We could use
> vscnprintf() and remove the off by one limit check.

Yes, that is a better patch. The previous one wasn't really fixing
anything. But printing truncated output is better than nothing.

Want to send it officially?

Thanks,

-- Steve

> 
> regards,
> dan carpenter
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 42a822d..ab76b7b 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -2160,9 +2160,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
>  		goto out;
>  	}
>  
> -	len = vsnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
> -	if (len > TRACE_BUF_SIZE)
> -		goto out;
> +	len = vscnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
>  
>  	local_save_flags(flags);
>  	size = sizeof(*entry) + len + 1;
> @@ -2173,8 +2171,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
>  	entry = ring_buffer_event_data(event);
>  	entry->ip = ip;
>  
> -	memcpy(&entry->buf, tbuffer, len);
> -	entry->buf[len] = '\0';
> +	memcpy(&entry->buf, tbuffer, len + 1);
>  	if (!call_filter_check_discard(call, entry, buffer, event)) {
>  		__buffer_unlock_commit(buffer, event);
>  		ftrace_trace_stack(buffer, flags, 6, pc);

Re: [patch] tracing: off by one in __trace_array_vprintk()

[Dan Carpenter]

On Wed, Nov 26, 2014 at 10:22:44AM -0500, Steven Rostedt wrote:
> On Wed, 26 Nov 2014 18:05:41 +0300
> Dan Carpenter <dan.carpenter@oracle.com> wrote:
> 
> > On Wed, Nov 26, 2014 at 09:43:06AM -0500, Steven Rostedt wrote:
> > > I highly doubt it's much of a speed up. And we do that by sacrificing
> > > that one byte of buffer, which would lose the printk if len does equal
> > > TRACE_BUF_SIZE.
> > > 
> > > I don't see a bug here. What exactly are you trying to fix?
> > 
> > Heh.  vsnprintf() is going to put a NUL char at the end of the string
> > even if you don't plan to use it.  :P
> > 
> > Another option would be to just print truncated output.  We could use
> > vscnprintf() and remove the off by one limit check.
> 
> Yes, that is a better patch. The previous one wasn't really fixing
> anything. But printing truncated output is better than nothing.
> 
> Want to send it officially?
> 

Will do.

regards,
dan carpenter

[patch v2] tracing: truncated output is better than nothing

[Dan Carpenter]

The initial reason for this patch is that I noticed that:

	if (len > TRACE_BUF_SIZE)

is off by one.  In this code, if len = TRACE_BUF_SIZE, then it means we
have truncated the last character off the output string.  If we truncate
two or more characters then we exit without printing.

After some discussion, we decided that printing truncated data is better
than not printing at all so we should just use vscnprintf() and remove
the test entirely.  Also I have updated memcpy() to copy the NUL char
instead of setting the NUL in a separate step.

Signed-off-by: Dan Carpenter <dan.carpenter@oracle.com>

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 42a822d..ab76b7b 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2160,9 +2160,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 		goto out;
 	}
 
-	len = vsnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
-	if (len > TRACE_BUF_SIZE)
-		goto out;
+	len = vscnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
 
 	local_save_flags(flags);
 	size = sizeof(*entry) + len + 1;
@@ -2173,8 +2171,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 	entry = ring_buffer_event_data(event);
 	entry->ip = ip;
 
-	memcpy(&entry->buf, tbuffer, len);
-	entry->buf[len] = '\0';
+	memcpy(&entry->buf, tbuffer, len + 1);
 	if (!call_filter_check_discard(call, entry, buffer, event)) {
 		__buffer_unlock_commit(buffer, event);
 		ftrace_trace_stack(buffer, flags, 6, pc);