[PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[Nikita Yushchenko]

When trace_check_vprintf() extracts parts of the format string and
passes those to trace_seq_printf() together with va_list, it expects
that trace_seq_printf() consumes arguments from va_list, as defined
by the passed format substring.

However, trace_seq_printf() has a special path for overflow handling,
that does not consume any arguments from va_list. This causes va_list
to get out of sync with format string processing, the next va_arg()
inside trace_check_vprintf() gets wrong argument, and WARN_ON_ONCE()
hits.

This situation easily triggers by ftrace_stress_test from LTP.

Fix that by adding a dummy vsnprintf() call to the overflow path inside
trace_seq_printf() to ensure args from va_list are still consumed.

Signed-off-by: Nikita Yushchenko <nikita.yushchenko@virtuozzo.com>
---
 kernel/trace/trace_seq.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c
index 9c90b3a7dce2..3551b5e18aa2 100644
--- a/kernel/trace/trace_seq.c
+++ b/kernel/trace/trace_seq.c
@@ -141,9 +141,15 @@ EXPORT_SYMBOL_GPL(trace_seq_bitmask);
 void trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
 {
 	unsigned int save_len = s->seq.len;
+	char buf[1];
 
-	if (s->full)
+	if (s->full) {
+		/* Consume args from va_list before returning, some callers
+		 * expect that.
+		 */
+		vsnprintf(buf, sizeof(buf), fmt, args);
 		return;
+	}
 
 	__trace_seq_init(s);
 
-- 
2.30.2

Re: [PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[Steven Rostedt]

On Wed, 17 Nov 2021 21:37:20 +0300
Nikita Yushchenko <nikita.yushchenko@virtuozzo.com> wrote:

> When trace_check_vprintf() extracts parts of the format string and
> passes those to trace_seq_printf() together with va_list, it expects
> that trace_seq_printf() consumes arguments from va_list, as defined
> by the passed format substring.
> 
> However, trace_seq_printf() has a special path for overflow handling,
> that does not consume any arguments from va_list. This causes va_list
> to get out of sync with format string processing, the next va_arg()
> inside trace_check_vprintf() gets wrong argument, and WARN_ON_ONCE()
> hits.
> 
> This situation easily triggers by ftrace_stress_test from LTP.
> 
> Fix that by adding a dummy vsnprintf() call to the overflow path inside
> trace_seq_printf() to ensure args from va_list are still consumed.

Hi Nikita,

> 
> Signed-off-by: Nikita Yushchenko <nikita.yushchenko@virtuozzo.com>
> ---
>  kernel/trace/trace_seq.c | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c
> index 9c90b3a7dce2..3551b5e18aa2 100644
> --- a/kernel/trace/trace_seq.c
> +++ b/kernel/trace/trace_seq.c
> @@ -141,9 +141,15 @@ EXPORT_SYMBOL_GPL(trace_seq_bitmask);
>  void trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
>  {
>  	unsigned int save_len = s->seq.len;
> +	char buf[1];
>  
> -	if (s->full)
> +	if (s->full) {
> +		/* Consume args from va_list before returning, some callers
> +		 * expect that.

First, only the networking code uses the /* comment ... for multiline
comments. The rest of the kernel uses:

		/*
		 * Consume ...
		 */

format for multi line comments.

But regardless. Consumers do not expect va_list to be consumed if it is
full. The one use case that does is buggy.

> +		 */
> +		vsnprintf(buf, sizeof(buf), fmt, args);
>  		return;
> +	}
>  
>  	__trace_seq_init(s);
>  

The real fix is:

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index f9139dc1262c..7aa5ea5ca912 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3654,6 +3654,10 @@ static bool trace_safe_str(struct trace_iterator *iter, const char *str)
 	struct trace_event *trace_event;
 	struct trace_event_call *event;
 
+	/* if seq is full, then we can't test it */
+	if (iter->seq->full)
+		return true;
+
 	/* OK if part of the event data */
 	if ((addr >= (unsigned long)iter->ent) &&
 	    (addr < (unsigned long)iter->ent + iter->ent_size))


Cheers,

-- Steve

Re: [PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[Steven Rostedt]

On Wed, 17 Nov 2021 18:38:27 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> The real fix is:
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index f9139dc1262c..7aa5ea5ca912 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3654,6 +3654,10 @@ static bool trace_safe_str(struct trace_iterator *iter, const char *str)
>  	struct trace_event *trace_event;
>  	struct trace_event_call *event;
>  
> +	/* if seq is full, then we can't test it */
> +	if (iter->seq->full)
> +		return true;
> +
>  	/* OK if part of the event data */
>  	if ((addr >= (unsigned long)iter->ent) &&
>  	    (addr < (unsigned long)iter->ent + iter->ent_size))

BTW, feel free to respin the patch and send a v2 and just add:

Suggested-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

Re: [PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[Nikita Yushchenko]

Hi

> The real fix is:
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index f9139dc1262c..7aa5ea5ca912 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3654,6 +3654,10 @@ static bool trace_safe_str(struct trace_iterator *iter, const char *str)
>   	struct trace_event *trace_event;
>   	struct trace_event_call *event;
>   
> +	/* if seq is full, then we can't test it */
> +	if (iter->seq->full)
> +		return true;
> +

What I don't like here is - trace_check_vprintf() will still extract wrong positional arguments, and use 
the result as part of it's logic.

Although with your change such use becomes a no-op, this is unintuitive and can turn easily into real 
problems with future changes.

And, the above comment is inexact...  why we can't test? We can, testing code does no depend on 
iter->seq. What we can't is - reliably extract str to test.

If testing seq->full condition is preferred over forcibly consuming args from va_list, then such a test 
shall be done before trace_check_vprintf() tries to use va_arg(). Will submit a patch doing that.

Nikita

[PATCH] trace: don't use out-of-sync va_list in event printing

[Nikita Yushchenko]

If trace_seq becomes full, trace_seq_vprintf() no longer consumes
arguments from va_list, making va_list out of sync with format
processing by trace_check_vprintf().

This causes va_arg() in trace_check_vprintf() to return wrong
positional argument, which results into a WARN_ON_ONCE() hit.

ftrace_stress_test from LTP triggers this situation.

Fix it by explicitly avoiding further use if va_list at the point
when it's consistency can no longer be guaranteed.

Signed-off-by: Nikita Yushchenko <nikita.yushchenko@virtuozzo.com>
---
 kernel/trace/trace.c | 12 ++++++++++++
 1 file changed, 12 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a1adb29ef5c1..3f527c2e08f2 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3826,6 +3826,18 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		iter->fmt[i] = '\0';
 		trace_seq_vprintf(&iter->seq, iter->fmt, ap);
 
+		/*
+		 * If iter->seq is full, the above call no longer guarantees
+		 * that ap is in sync with fmt processing, and further calls
+		 * to va_arg() can return wrong positional arguments.
+		 *
+		 * Ensure that ap is no longer used in this case.
+		 */
+		if (iter->seq.full) {
+			p = "";
+			break;
+		}
+
 		if (star)
 			len = va_arg(ap, int);
 
-- 
2.30.2

Re: [PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[Steven Rostedt]

On Thu, 18 Nov 2021 07:57:33 +0300
Nikita Yushchenko <nikita.yushchenko@virtuozzo.com> wrote:

> What I don't like here is - trace_check_vprintf() will still extract wrong positional arguments, and use 
> the result as part of it's logic.
> 
> Although with your change such use becomes a no-op, this is unintuitive and can turn easily into real 
> problems with future changes.

That trace_check_vprintf() is just full of unintuitive logic ;-)

Which is why I prefer to keep any remnants of that code in that code and
not spread it around. 

> 
> And, the above comment is inexact...  why we can't test? We can, testing code does no depend on 
> iter->seq. What we can't is - reliably extract str to test.
> 
> If testing seq->full condition is preferred over forcibly consuming args from va_list, then such a test 
> shall be done before trace_check_vprintf() tries to use va_arg(). Will submit a patch doing that.

I'm happy with that patch, but can you please resend it as a top level
patch and not a reply, otherwise my patchwork doesn't catch it and my
scripts will not work on it.

Thanks,

-- Steve

Re: [PATCH] tracing: fix va_list breakage in trace_check_vprintf()

[Nikita Yushchenko]

Hi

>> If testing seq->full condition is preferred over forcibly consuming args from va_list, then such a test
>> shall be done before trace_check_vprintf() tries to use va_arg(). Will submit a patch doing that.
> 
> I'm happy with that patch, but can you please resend it as a top level
> patch and not a reply, otherwise my patchwork doesn't catch it and my
> scripts will not work on it.

Sure, doing that now.

Nikita

[PATCH] trace: don't use out-of-sync va_list in event printing

[Nikita Yushchenko]

If trace_seq becomes full, trace_seq_vprintf() no longer consumes
arguments from va_list, making va_list out of sync with format
processing by trace_check_vprintf().

This causes va_arg() in trace_check_vprintf() to return wrong
positional argument, which results into a WARN_ON_ONCE() hit.

ftrace_stress_test from LTP triggers this situation.

Fix it by explicitly avoiding further use if va_list at the point
when it's consistency can no longer be guaranteed.

Signed-off-by: Nikita Yushchenko <nikita.yushchenko@virtuozzo.com>
---
 kernel/trace/trace.c | 12 ++++++++++++
 1 file changed, 12 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a1adb29ef5c1..3f527c2e08f2 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3826,6 +3826,18 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		iter->fmt[i] = '\0';
 		trace_seq_vprintf(&iter->seq, iter->fmt, ap);
 
+		/*
+		 * If iter->seq is full, the above call no longer guarantees
+		 * that ap is in sync with fmt processing, and further calls
+		 * to va_arg() can return wrong positional arguments.
+		 *
+		 * Ensure that ap is no longer used in this case.
+		 */
+		if (iter->seq.full) {
+			p = "";
+			break;
+		}
+
 		if (star)
 			len = va_arg(ap, int);
 
-- 
2.30.2