| 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 |
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 >
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
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 --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 ||
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(+)