diff mbox series

[v1] libtraceevent: Fix event-parse memory leak in process_cond

Message ID 20240430073908.1706482-1-irogers@google.com (mailing list archive)
State Accepted
Commit 76a0eb8d5a20c69120a5f8b4c12f4da0cdc15bb5
Headers show
Series [v1] libtraceevent: Fix event-parse memory leak in process_cond | expand

Commit Message

Ian Rogers April 30, 2024, 7:39 a.m. UTC
Leak sanitizer was reporting a stack trace with perf:
```
$ perf stat -e 'kvm:kvm_inj_exception' true

 Performance counter stats for 'true':

                 0      kvm:kvm_inj_exception

       0.001701473 seconds time elapsed

       0.000000000 seconds user
       0.001865000 seconds sys

=================================================================
==1705137==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 2 byte(s) in 1 object(s) allocated from:
    #0 0x7f413ee80778 in __interceptor_strdup ../../../../src/libsanitizer/asan/asan_interceptors.cpp:454
    #1 0x7f413ecb7b66 in __read_token libtraceevent/src/event-parse.c:1274
    #2 0x7f413ecb85bb in read_token libtraceevent/src/event-parse.c:1432
    #3 0x7f413ecbeaaa in process_entry libtraceevent/src/event-parse.c:2554
    #4 0x7f413ecc54ae in process_arg_token libtraceevent/src/event-parse.c:3698
    #5 0x7f413ecbb52e in process_arg libtraceevent/src/event-parse.c:2017
    #6 0x7f413ecbd05a in process_op libtraceevent/src/event-parse.c:2357
    #7 0x7f413ecc5a56 in process_arg_token libtraceevent/src/event-parse.c:3752
    #8 0x7f413ecbb52e in process_arg libtraceevent/src/event-parse.c:2017
    #9 0x7f413ecc5dd6 in event_read_print_args libtraceevent/src/event-parse.c:3791
    #10 0x7f413ecc6511 in event_read_print libtraceevent/src/event-parse.c:3879
    #11 0x7f413ecda16c in parse_format libtraceevent/src/event-parse.c:7808
    #12 0x7f413ecda667 in __parse_event libtraceevent/src/event-parse.c:7866
    #13 0x7f413ecda71b in tep_parse_format libtraceevent/src/event-parse.c:7908
    #14 0x561672439029 in tp_format util/trace-event.c:94
    #15 0x561672439141 in trace_event__tp_format util/trace-event.c:109
    #16 0x56167230a429 in evsel__newtp_idx util/evsel.c:472
    #17 0x561672329f99 in add_tracepoint util/parse-events.c:552
    #18 0x56167232a5b4 in add_tracepoint_event util/parse-events.c:627
    #19 0x56167232ebf2 in parse_events_add_tracepoint util/parse-events.c:1313
    #20 0x561672411e0e in parse_events_parse util/parse-events.y:500
    #21 0x561672332409 in parse_events__scanner util/parse-events.c:1878
    #22 0x561672333cd4 in __parse_events util/parse-events.c:2146
    #23 0x561672334e74 in parse_events_option util/parse-events.c:2349
    #24 0x56167269ec23 in get_value tools/lib/subcmd/parse-options.c:251
    #25 0x56167269fe65 in parse_short_opt tools/lib/subcmd/parse-options.c:351
    #26 0x5616726a0e4d in parse_options_step tools/lib/subcmd/parse-options.c:539
    #27 0x5616726a1d86 in parse_options_subcommand tools/lib/subcmd/parse-options.c:654
    #28 0x5616720e6ad2 in cmd_stat tools/perf/builtin-stat.c:2531
    #29 0x5616722b0f5d in run_builtin tools/perf/perf.c:350
$ cat /sys/kernel/tracing/events/kvm/kvm_inj_exception/format
name: kvm_inj_exception
ID: 1956
format:
        field:unsigned short common_type;       offset:0;       size:2; signed:0;
        field:unsigned char common_flags;       offset:2;       size:1; signed:0;
        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
        field:int common_pid;   offset:4;       size:4; signed:1;

        field:u8 exception;     offset:8;       size:1; signed:0;
        field:u8 has_error;     offset:9;       size:1; signed:0;
        field:u32 error_code;   offset:12;      size:4; signed:0;
        field:bool reinjected;  offset:16;      size:1; signed:0;

print fmt: "%s%s%s%s%s", __print_symbolic(REC->exception, { 0, "#" "DE" }, { 1, "#" "DB" }, { 3, "#" "BP" }, { 4, "#" "OF" }, { 5, "#" "BR" }, { 6, "#" "UD" }, { 7, "#" "NM" }, { 8, "#" "DF" }, { 10, "#" "TS" }, { 11, "#" "NP" }, { 12, "#" "SS" }, { 13, "#" "GP" }, { 14, "#" "PF" }, { 16, "#" "MF" }, { 17, "#" "AC" }, { 18, "#" "MC" }), !REC->has_error ? "" : " (", !REC->has_error ? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" : ")", REC->reinjected ? " [reinjected]" : ""
```

The issue appears to be that when process_cond returns an error,
callers clear the variable holding the string but the string was never
freed. This change adds the free when process_cond returns
TEP_EVENT_ERROR.

Signed-off-by: Ian Rogers <irogers@google.com>
---
 src/event-parse.c | 2 ++
 1 file changed, 2 insertions(+)

Comments

Ian Rogers April 30, 2024, 8:03 a.m. UTC | #1
On Tue, Apr 30, 2024 at 12:39 AM Ian Rogers <irogers@google.com> wrote:
>
> Leak sanitizer was reporting a stack trace with perf:
> ```
> $ perf stat -e 'kvm:kvm_inj_exception' true
>
>  Performance counter stats for 'true':
>
>                  0      kvm:kvm_inj_exception
>
>        0.001701473 seconds time elapsed
>
>        0.000000000 seconds user
>        0.001865000 seconds sys
>
> =================================================================
> ==1705137==ERROR: LeakSanitizer: detected memory leaks
>
> Direct leak of 2 byte(s) in 1 object(s) allocated from:
>     #0 0x7f413ee80778 in __interceptor_strdup ../../../../src/libsanitizer/asan/asan_interceptors.cpp:454
>     #1 0x7f413ecb7b66 in __read_token libtraceevent/src/event-parse.c:1274
>     #2 0x7f413ecb85bb in read_token libtraceevent/src/event-parse.c:1432
>     #3 0x7f413ecbeaaa in process_entry libtraceevent/src/event-parse.c:2554
>     #4 0x7f413ecc54ae in process_arg_token libtraceevent/src/event-parse.c:3698
>     #5 0x7f413ecbb52e in process_arg libtraceevent/src/event-parse.c:2017
>     #6 0x7f413ecbd05a in process_op libtraceevent/src/event-parse.c:2357
>     #7 0x7f413ecc5a56 in process_arg_token libtraceevent/src/event-parse.c:3752
>     #8 0x7f413ecbb52e in process_arg libtraceevent/src/event-parse.c:2017
>     #9 0x7f413ecc5dd6 in event_read_print_args libtraceevent/src/event-parse.c:3791
>     #10 0x7f413ecc6511 in event_read_print libtraceevent/src/event-parse.c:3879
>     #11 0x7f413ecda16c in parse_format libtraceevent/src/event-parse.c:7808
>     #12 0x7f413ecda667 in __parse_event libtraceevent/src/event-parse.c:7866
>     #13 0x7f413ecda71b in tep_parse_format libtraceevent/src/event-parse.c:7908
>     #14 0x561672439029 in tp_format util/trace-event.c:94
>     #15 0x561672439141 in trace_event__tp_format util/trace-event.c:109
>     #16 0x56167230a429 in evsel__newtp_idx util/evsel.c:472
>     #17 0x561672329f99 in add_tracepoint util/parse-events.c:552
>     #18 0x56167232a5b4 in add_tracepoint_event util/parse-events.c:627
>     #19 0x56167232ebf2 in parse_events_add_tracepoint util/parse-events.c:1313
>     #20 0x561672411e0e in parse_events_parse util/parse-events.y:500
>     #21 0x561672332409 in parse_events__scanner util/parse-events.c:1878
>     #22 0x561672333cd4 in __parse_events util/parse-events.c:2146
>     #23 0x561672334e74 in parse_events_option util/parse-events.c:2349
>     #24 0x56167269ec23 in get_value tools/lib/subcmd/parse-options.c:251
>     #25 0x56167269fe65 in parse_short_opt tools/lib/subcmd/parse-options.c:351
>     #26 0x5616726a0e4d in parse_options_step tools/lib/subcmd/parse-options.c:539
>     #27 0x5616726a1d86 in parse_options_subcommand tools/lib/subcmd/parse-options.c:654
>     #28 0x5616720e6ad2 in cmd_stat tools/perf/builtin-stat.c:2531
>     #29 0x5616722b0f5d in run_builtin tools/perf/perf.c:350
> $ cat /sys/kernel/tracing/events/kvm/kvm_inj_exception/format
> name: kvm_inj_exception
> ID: 1956
> format:
>         field:unsigned short common_type;       offset:0;       size:2; signed:0;
>         field:unsigned char common_flags;       offset:2;       size:1; signed:0;
>         field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
>         field:int common_pid;   offset:4;       size:4; signed:1;
>
>         field:u8 exception;     offset:8;       size:1; signed:0;
>         field:u8 has_error;     offset:9;       size:1; signed:0;
>         field:u32 error_code;   offset:12;      size:4; signed:0;
>         field:bool reinjected;  offset:16;      size:1; signed:0;
>
> print fmt: "%s%s%s%s%s", __print_symbolic(REC->exception, { 0, "#" "DE" }, { 1, "#" "DB" }, { 3, "#" "BP" }, { 4, "#" "OF" }, { 5, "#" "BR" }, { 6, "#" "UD" }, { 7, "#" "NM" }, { 8, "#" "DF" }, { 10, "#" "TS" }, { 11, "#" "NP" }, { 12, "#" "SS" }, { 13, "#" "GP" }, { 14, "#" "PF" }, { 16, "#" "MF" }, { 17, "#" "AC" }, { 18, "#" "MC" }), !REC->has_error ? "" : " (", !REC->has_error ? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" : ")", REC->reinjected ? " [reinjected]" : ""
> ```

Some more context. The place in the input where the leak appears is of
a string "?" read as a token at:
? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" :
")", REC->reinjected ? " [reinjected]" : ""

Laboriously debugged using printf. My belief that errors should clean
up allocations comes from:
https://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git/tree/src/event-parse.c#n3754

The error comes from:
https://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git/tree/src/event-parse.c#n2082
and that error originally comes from:
https://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git/tree/src/event-parse.c#n2332
where the bad token in "}". The stack trace is:

#0  process_op (event=0x6080000003a0, arg=0x604000000ed0,
tok=0x7ffff2a01920) at event-parse.c:2333
#1  0x00007ffff5efba81 in process_arg_token (event=0x6080000003a0,
arg=0x604000000ed0,
   tok=0x7ffff2912360, type=TEP_EVENT_OP) at event-parse.c:3754
#2  0x00007ffff5ef152f in process_arg (event=0x6080000003a0,
arg=0x604000000ed0,
   tok=0x7ffff2912360) at event-parse.c:2017
#3  0x00007ffff5ef6fdb in process_fields (event=0x6080000003a0,
list=0x604000000e68,
   tok=0x7ffff29122a0) at event-parse.c:2939
#4  0x00007ffff5ef7c0a in process_symbols (event=0x6080000003a0,
arg=0x604000000e50,
   tok=0x7ffff2a01820) at event-parse.c:3076
#5  0x00007ffff5efaebd in process_function (event=0x6080000003a0,
arg=0x604000000e50,
   token=0x603000001840 "\270\002", tok=0x7ffff2a01820) at event-parse.c:3626
#6  0x00007ffff5efb631 in process_arg_token (event=0x6080000003a0,
arg=0x604000000e50,
   tok=0x7ffff29121e0, type=TEP_EVENT_DELIM) at event-parse.c:3715
#7  0x00007ffff5ef152f in process_arg (event=0x6080000003a0,
arg=0x604000000e50,
   tok=0x7ffff29121e0) at event-parse.c:2017
#8  0x00007ffff5ef19c5 in process_cond (event=0x6080000003a0,
top=0x604000000cd0,
   tok=0x7ffff2a016a0) at event-parse.c:2082
#9  0x00007ffff5ef3364 in process_op (event=0x6080000003a0,
arg=0x604000000cd0, tok=0x7ffff2a016a0)
   at event-parse.c:2375
#10 0x00007ffff5ef44e1 in process_op (event=0x6080000003a0,
arg=0x604000000cd0, tok=0x7ffff2a016a0)
   at event-parse.c:2500
#11 0x00007ffff5efba81 in process_arg_token (event=0x6080000003a0,
arg=0x604000000cd0,
   tok=0x7ffff2910e20, type=TEP_EVENT_OP) at event-parse.c:3754
#12 0x00007ffff5ef152f in process_arg (event=0x6080000003a0,
arg=0x604000000cd0,
   tok=0x7ffff2910e20) at event-parse.c:2017
#13 0x00007ffff5efbe01 in event_read_print_args (event=0x6080000003a0,
list=0x604000000b10)
   at event-parse.c:3793
#14 0x00007ffff5efc53c in event_read_print (event=0x6080000003a0) at
event-parse.c:3881
#15 0x00007ffff5f10197 in parse_format (eventp=0x7ffff3008020,
tep=0x6120000004c0,
   buf=0x619000000a80 "name: kvm_inj_exception\nID:
1956\nformat:\n\tfield:unsigned short common_ty
pe;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char
common_flags;\toffset:2;\tsize:1;\tsigned:
0;\n\tfield:unsigned char common_preem"..., size=992, sys=0x602000005450 "kvm")
   at event-parse.c:7810
#16 0x00007ffff5f10692 in __parse_event (tep=0x6120000004c0,
eventp=0x7ffff3008020,
   buf=0x619000000a80 "name: kvm_inj_exception\nID:
1956\nformat:\n\tfield:unsigned short common_ty
pe;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char
common_flags;\toffset:2;\tsize:1;\tsigned:
0;\n\tfield:unsigned char common_preem"..., size=992, sys=0x602000005450 "kvm")
   at event-parse.c:7868
#17 0x00007ffff5f10746 in tep_parse_format (tep=0x6120000004c0,
eventp=0x7ffff3008020,
   buf=0x619000000a80 "name: kvm_inj_exception\nID:
1956\nformat:\n\tfield:unsigned short common_ty
pe;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char
common_flags;\toffset:2;\tsize:1;\tsigned:
0;\n\tfield:unsigned char common_preem"..., size=992, sys=0x602000005450 "kvm")
   at event-parse.c:7910
#18 0x0000555555b1e02a in tp_format (sys=0x602000005450 "kvm",
   name=0x6030000013f0 "kvm_inj_exception") at util/trace-event.c:94

So I think the error is in the "{}" in
"__print_symbolic(REC->error_code, { })" but I'm just guessing.

Thanks,
Ian

> The issue appears to be that when process_cond returns an error,
> callers clear the variable holding the string but the string was never
> freed. This change adds the free when process_cond returns
> TEP_EVENT_ERROR.
>
> Signed-off-by: Ian Rogers <irogers@google.com>
> ---
>  src/event-parse.c | 2 ++
>  1 file changed, 2 insertions(+)
>
> diff --git a/src/event-parse.c b/src/event-parse.c
> index d607556..b6ae67e 100644
> --- a/src/event-parse.c
> +++ b/src/event-parse.c
> @@ -2373,6 +2373,8 @@ process_op(struct tep_event *event, struct tep_print_arg *arg, char **tok)
>
>                 /* it will set arg->op.right */
>                 type = process_cond(event, arg, tok);
> +               if (type == TEP_EVENT_ERROR)
> +                       free(token);
>
>         } else if (strcmp(token, ">>") == 0 ||
>                    strcmp(token, "<<") == 0 ||
> --
> 2.44.0.769.g3c40516874-goog
>
Steven Rostedt May 17, 2024, 12:40 a.m. UTC | #2
On Tue, 30 Apr 2024 01:03:15 -0700
Ian Rogers <irogers@google.com> wrote:

> > print fmt: "%s%s%s%s%s", __print_symbolic(REC->exception, { 0, "#" "DE" }, { 1, "#" "DB" }, { 3, "#" "BP" }, { 4, "#" "OF" }, { 5, "#" "BR" }, { 6, "#" "UD" }, { 7, "#" "NM" }, { 8, "#" "DF" }, { 10, "#" "TS" }, { 11, "#" "NP" }, { 12, "#" "SS" }, { 13, "#" "GP" }, { 14, "#" "PF" }, { 16, "#" "MF" }, { 17, "#" "AC" }, { 18, "#" "MC" }), !REC->has_error ? "" : " (", !REC->has_error ? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" : ")", REC->reinjected ? " [reinjected]" : ""
> > ```  
> 
> Some more context. The place in the input where the leak appears is of
> a string "?" read as a token at:
> ? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" :
> ")", REC->reinjected ? " [reinjected]" : ""

That probably is the cause. That should get handled.

-- Steve
Ian Rogers May 28, 2024, 3:50 p.m. UTC | #3
On Thu, May 16, 2024 at 5:40 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Tue, 30 Apr 2024 01:03:15 -0700
> Ian Rogers <irogers@google.com> wrote:
>
> > > print fmt: "%s%s%s%s%s", __print_symbolic(REC->exception, { 0, "#" "DE" }, { 1, "#" "DB" }, { 3, "#" "BP" }, { 4, "#" "OF" }, { 5, "#" "BR" }, { 6, "#" "UD" }, { 7, "#" "NM" }, { 8, "#" "DF" }, { 10, "#" "TS" }, { 11, "#" "NP" }, { 12, "#" "SS" }, { 13, "#" "GP" }, { 14, "#" "PF" }, { 16, "#" "MF" }, { 17, "#" "AC" }, { 18, "#" "MC" }), !REC->has_error ? "" : " (", !REC->has_error ? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" : ")", REC->reinjected ? " [reinjected]" : ""
> > > ```
> >
> > Some more context. The place in the input where the leak appears is of
> > a string "?" read as a token at:
> > ? "" : __print_symbolic(REC->error_code, { }), !REC->has_error ? "" :
> > ")", REC->reinjected ? " [reinjected]" : ""
>
> That probably is the cause. That should get handled.

Thanks for landing this, glad I got the logic right.

Ian

> -- Steve
diff mbox series

Patch

diff --git a/src/event-parse.c b/src/event-parse.c
index d607556..b6ae67e 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -2373,6 +2373,8 @@  process_op(struct tep_event *event, struct tep_print_arg *arg, char **tok)
 
 		/* it will set arg->op.right */
 		type = process_cond(event, arg, tok);
+		if (type == TEP_EVENT_ERROR)
+			free(token);
 
 	} else if (strcmp(token, ">>") == 0 ||
 		   strcmp(token, "<<") == 0 ||