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@xxxxxxxxxx> 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