[PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[Yang Jihong]

print_trace_line may overflow seq_file buffer. If the event is not
consumed, the while loop keeps peeking this event, causing a infinite loop.

Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
 kernel/trace/trace.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 47a44b055a1d..2a8d5c68c29b 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6788,6 +6788,19 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
 		if (ret == TRACE_TYPE_PARTIAL_LINE) {
 			/* don't print partial lines */
 			iter->seq.seq.len = save_len;
+
+			/*
+			 * If one trace_line of the tracer overflows seq_file
+			 * buffer, trace_seq_to_user returns -EBUSY because
+			 * nothing in the sequence (iter->seq.seq.len = \
+			 * iter->seq.seq.readpos = 0).
+			 * In this case, we need to consume, otherwise,
+			 * "while" will peek this event next time, resulting
+			 * in an infinite loop.
+			 */
+			if (trace_seq_has_overflowed(&iter->seq))
+				trace_consume(iter);
+
 			break;
 		}
 		if (ret != TRACE_TYPE_NO_CONSUME)
-- 
2.30.GIT

Re: [PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[Steven Rostedt]

On Mon, 14 Nov 2022 10:29:46 +0800
Yang Jihong <yangjihong1@huawei.com> wrote:

> print_trace_line may overflow seq_file buffer. If the event is not
> consumed, the while loop keeps peeking this event, causing a infinite loop.
> 
> Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
> ---
>  kernel/trace/trace.c | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 47a44b055a1d..2a8d5c68c29b 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -6788,6 +6788,19 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
>  		if (ret == TRACE_TYPE_PARTIAL_LINE) {
>  			/* don't print partial lines */
>  			iter->seq.seq.len = save_len;
> +
> +			/*
> +			 * If one trace_line of the tracer overflows seq_file
> +			 * buffer, trace_seq_to_user returns -EBUSY because
> +			 * nothing in the sequence (iter->seq.seq.len = \
> +			 * iter->seq.seq.readpos = 0).
> +			 * In this case, we need to consume, otherwise,
> +			 * "while" will peek this event next time, resulting
> +			 * in an infinite loop.
> +			 */
> +			if (trace_seq_has_overflowed(&iter->seq))
> +				trace_consume(iter);

Instead of consuming it, I think the right solution is to print the partial
line. Something like:

			if (trace_seq_has_overflowed(&iter->seq)) {
				char dots[] = "...";

				iter->seq.seq.len -= sizeof(dots) + 1;
				iter->seq.seq.full = 0;
				trace_seq_puts(&iter->seq, dots);
				trace_consume(iter);
				break;
			}

			iter->seq.seq.len = save_len;
			break;

That way we can see the broken trace event and not just silently drop it.

-- Steve

> +
>  			break;
>  		}
>  		if (ret != TRACE_TYPE_NO_CONSUME)

Re: [PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[Yang Jihong]

Hello,

On 2022/11/18 5:40, Steven Rostedt wrote:
> On Mon, 14 Nov 2022 10:29:46 +0800
> Yang Jihong <yangjihong1@huawei.com> wrote:
> 
>> print_trace_line may overflow seq_file buffer. If the event is not
>> consumed, the while loop keeps peeking this event, causing a infinite loop.
>>
>> Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
>> ---
>>   kernel/trace/trace.c | 13 +++++++++++++
>>   1 file changed, 13 insertions(+)
>>
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index 47a44b055a1d..2a8d5c68c29b 100644
>> --- a/kernel/trace/trace.c
>> +++ b/kernel/trace/trace.c
>> @@ -6788,6 +6788,19 @@ tracing_read_pipe(struct file *filp, char __user *ubuf,
>>   		if (ret == TRACE_TYPE_PARTIAL_LINE) {
>>   			/* don't print partial lines */
>>   			iter->seq.seq.len = save_len;
>> +
>> +			/*
>> +			 * If one trace_line of the tracer overflows seq_file
>> +			 * buffer, trace_seq_to_user returns -EBUSY because
>> +			 * nothing in the sequence (iter->seq.seq.len = \
>> +			 * iter->seq.seq.readpos = 0).
>> +			 * In this case, we need to consume, otherwise,
>> +			 * "while" will peek this event next time, resulting
>> +			 * in an infinite loop.
>> +			 */
>> +			if (trace_seq_has_overflowed(&iter->seq))
>> +				trace_consume(iter);
> 
> Instead of consuming it, I think the right solution is to print the partial
> line. Something like:
> 
> 			if (trace_seq_has_overflowed(&iter->seq)) {
> 				char dots[] = "...";
> 
> 				iter->seq.seq.len -= sizeof(dots) + 1;
> 				iter->seq.seq.full = 0;
> 				trace_seq_puts(&iter->seq, dots);
> 				trace_consume(iter);
> 				break;
> 			}
> 
> 			iter->seq.seq.len = save_len;
> 			break;
> 
> That way we can see the broken trace event and not just silently drop it.
> 
Ok, will change in next version.(Because iter->seq.seq.len may be 
smaller than strlen(dots), direct subtraction here may not be appropriate.)

Thanks,
Yang

Re: [PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[Steven Rostedt]

On Fri, 18 Nov 2022 18:21:12 +0800
Yang Jihong <yangjihong1@huawei.com> wrote:

> > That way we can see the broken trace event and not just silently drop it.
> >   
> Ok, will change in next version.(Because iter->seq.seq.len may be 
> smaller than strlen(dots), direct subtraction here may not be appropriate.)

We should only need to do this if the len is maxed out.

Hmm, len is only updated if it did actually copy it.

Perhaps we could just add:

	trace_seq_puts(&iter->seq, "[LINE TOO BIG]\n");

And perhaps that will work?

Anyway, what is triggering this?

-- Steve

Re: [PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[Yang Jihong]

Hello,

On 2022/11/21 3:49, Steven Rostedt wrote:
> On Fri, 18 Nov 2022 18:21:12 +0800
> Yang Jihong <yangjihong1@huawei.com> wrote:
> 
>>> That way we can see the broken trace event and not just silently drop it.
>>>    
>> Ok, will change in next version.(Because iter->seq.seq.len may be
>> smaller than strlen(dots), direct subtraction here may not be appropriate.)
> 
> We should only need to do this if the len is maxed out.
> 
> Hmm, len is only updated if it did actually copy it.
> 
> Perhaps we could just add:
> 
> 	trace_seq_puts(&iter->seq, "[LINE TOO BIG]\n");
> 
> And perhaps that will work?
> 
Yes, as you mentioned in the v2 patch:

"The case I believe you are fixing, is the case were one 
print_trace_line() actually fills the entire trace_seq in one shot."
The problem I'm having is exactly that.

Just add "trace_seq_puts(&iter->seq, "[LINE TOO BIG]\n"); " can solve 
this problem.

But I thought it might happen. (Not yet. Is it possible to support new 
tracers in the future?)

   print_one_line {
     char buf[4090];                          // there's some data in 
the buf.
     trace_seq_puts(s, buf);                  // trace_seq buffer write 
successfully
     trace_seq_puts(s, "test, test, test\n"); // trace_seq buffer overflow
   }

If we want to print out the boken event (buf[4090]), we may need to 
reserve space as we did before.
If we don't consider this situation, we can just add 
"trace_seq_puts(&iter->seq, "[LINE TOO BIG]\n");", it's fine.

> Anyway, what is triggering this?
In my environment, this problem may be triggered in the following ways:
   # echo 1 > /sys/kernel/debug/tracing/options/blk_classic
   # echo 1 > /sys/kernel/debug/tracing/options/blk_cgroup
   # echo 1 > /sys/kernel/debug/tracing/events/enable
   # echo blk > /sys/kernel/debug/tracing/current_tracer
   # cat /sys/kernel/debug/tracing/trace_pipe > /dev/null

trace_pipe enter the blk_log_dump_pdu function through the following 
call stack:

tracing_read_pipe
   -> print_trace_line
     -> iter->trace->print_line (current_trace == blk)
	  -> blk_tracer_print_line
	    -> print_one_line
		  -> blk_log_generic
		    -> blk_log_dump_pdu

static void blk_log_dump_pdu(struct trace_seq *s,
         const struct trace_entry *ent, bool has_cg)
{
...
         for (i = 0; i < pdu_len; i++) {

                 trace_seq_printf(s, "%s%02x",
                                  i == 0 ? "" : " ", pdu_buf[i]);

                 /*
                  * stop when the rest is just zeros and indicate so
                  * with a ".." appended
                  */
                 if (i == end && end != pdu_len - 1) {
                         trace_seq_puts(s, " ..) ");
                         return;
                 }
         }
...
}
After the blk_classic option is enabled, blktrace writes all events in 
the ring buffer to the trace_seq buffer through blk_log_dump_pdu.
If the value of pdu_len is too large, the buffer overflow may occur.
(This problem may be caused by improper processing of blktrace.)

Thanks,
Yang

Re: [PATCH] tracing: Fix infinite loop in tracing_read_pipe on overflowed print_trace_line

[Yang Jihong]

Hello,

On 2022/11/21 3:49, Steven Rostedt wrote:
> On Fri, 18 Nov 2022 18:21:12 +0800
> Yang Jihong <yangjihong1@huawei.com> wrote:
> 
>>> That way we can see the broken trace event and not just silently drop it.
>>>    
>> Ok, will change in next version.(Because iter->seq.seq.len may be
>> smaller than strlen(dots), direct subtraction here may not be appropriate.)
> 
> We should only need to do this if the len is maxed out.
> 
> Hmm, len is only updated if it did actually copy it.
> 
> Perhaps we could just add:
> 
> 	trace_seq_puts(&iter->seq, "[LINE TOO BIG]\n");
> 
The v3 patch has been sent according to this solution.

Thanks,
Yang