On Tue, Apr 30, 2024 at 12:39 AM Ian Rogers <irogers@xxxxxxxxxx> 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@xxxxxxxxxx>
> ---
> 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
>
|