double free detected in tcache

[fpxu]

Running Ejabberd against OTP-27.3.4.6, and occasionally encounter the double free issue.

I add a breapoint at malloc_printerr() in gdb and got the backtrace:

(gdb) bt full
#0  0x00007f42c460d0c0 in malloc_printerr () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007f42c460efaf in _int_free () from /lib64/libc.so.6
No symbol table info available.
#2  0x00007f42c4611405 in free () from /lib64/libc.so.6
No symbol table info available.
#3  0x00007f42713fdf88 in EVP_MAC_free () from /lib64/libcrypto.so.3
No symbol table info available.
#4  0x00007f42713fdfe9 in EVP_MAC_CTX_free () from /lib64/libcrypto.so.3
No symbol table info available.
#5  0x000000000085f914 in run_resource_dtor (vbin=0x7f420683d578) at beam/erl_nif.c:2981
        msg_env = {env = {mod_nif = 0x1e4606c0, proc = 0x7f4273141878, hp = 0xc52160 <phony_heap>, hp_end = 0xc52160 <phony_heap>, heap_frag = 0x0, tmp_obj_list = 0x0, exception_thrown = 0, tracee = 0x0, exiting = 1546499616}, phony_proc = {common = {id = 18446744073709551603, 
              refc = {atmc = {counter = 0}, sint = 0}, timer = {counter = 0}, u = {alive = {started_interval = 0, reg = 0x0, links = 0x0, lt_monitors = 0x0, monitors = 0x0}, release = {later = 0, func = 0x0, data = 0x0, next = 0x0}}, tracee = {all_trace_flags = 0, 
                first_ref = 0x0}}, htop = 0xc52160 <phony_heap>, stop = 0xc52178 <phony_heap+24>, frame_pointer = 0x0, freason = 0, fvalue = 0, fcalls = 0, flags = 0, rcount = 0, schedule_count = 0 '\000', arity = 0 '\000', max_arg_reg = 0 '\000', arg_reg = 0x0, def_arg_reg = {
              0, 0, 0, 0, 0, 0}, heap = 0xc52160 <phony_heap>, hend = 0xc52178 <phony_heap+24>, abandoned_heap = 0x0, heap_sz = 0, min_heap_size = 0, min_vheap_size = 0, max_heap_size = 0, i = 0x0, catches = 0, return_trace_frames = 0, reds = 0, group_leader = 0, ftrace = 0, 
            next = 0x0, uniq = 0, sig_qs = {first = 0x0, last = 0x0, save = 0x0, mq_len = 0, cont = 0x0, cont_last = 0x0, nmsigs = {next = 0x0, last = 0x0}, mlenoffs = 0, recv_mrk_blk = 0x0, flags = 0}, bif_timers = 0x0, dictionary = 0x0, seq_trace_clock = 0, 
            seq_trace_lastcnt = 0, seq_trace_token = 0, u = {real_proc = 0x0, terminate = 0x0, initial = {module = 0, function = 0, arity = 0}}, current = 0x0, parent = 0, static_flags = 0, gen_gcs = 0, max_gen_gcs = 0, high_water = 0x0, old_hend = 0x0, old_htop = 0x0, 
            old_heap = 0x0, off_heap = {first = 0x0, overhead = 0}, wrt_bins = 0x0, mbuf = 0x0, live_hf_end = 0x0, msg_frag = 0x0, mbuf_sz = 0, psd = {counter = 0}, bin_vheap_sz = 0, bin_old_vheap_sz = 0, bin_old_vheap = 0, sys_task_qs = 0x0, dirty_sys_tasks = 0x0, state = {
              counter = 0}, xstate = {counter = 0}, sig_inq_contention_counter = 0, sig_inq = {first = 0x0, last = 0x0, mlenoffs = 0, nmsigs = {next = 0x0, last = 0x0}}, sig_inq_buffers = {counter = 0}, trace_msg_q = 0x0, lock = {flags = {counter = 0}, queue = {0x0, 0x0, 0x0, 
                0x0, 0x0}}, scheduler_data = 0x0, run_queue = {counter = 0}}}
        bin = 0x7f420683d578
        resource = 0x7f420683d5b0
        type = 0x1e462860
#6  0x000000000060dcb6 in handle_misc_aux_work (waiting=0, aux_work=2048, awdp=0x7f428431eff8) at beam/erl_process.c:1877
        mawp = 0x7f4284371da0
        q = 0x7f42843731c0
        q = <optimized out>
        mawp = <optimized out>
#7  handle_aux_work (awdp=awdp@entry=0x7f428431eff8, orig_aux_work=<optimized out>, waiting=waiting@entry=0) at beam/erl_process.c:2732
        aux_work = 2048
        ignore = 4095
        __erts_msacc_cache = <optimized out>
        __erts_msacc_state = <optimized out>
#8  0x000000000061dc8f in erts_schedule (esdp=0x7f428431ef00, p=<optimized out>, calls=<optimized out>) at beam/erl_process.c:9764
        aux_work = 3072
        leader_update = 1
        mps = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--
        mp = <optimized out>
        proxy_p = 0x0
        rq = 0x7f428431e240
        context_reds = 4000
        fcalls = 36007
        actual_reds = <optimized out>
        reds = <optimized out>
        flags = <optimized out>
        state = 24874
        is_normal_sched = <optimized out>
        sched_type = ERTS_SCHED_NORMAL
        __erts_msacc_cache = 0x0
        __erts_msacc_state = <optimized out>
        check_activities_to_run = <optimized out>
        continue_check_activities_to_run = <optimized out>
        continue_check_activities_to_run_known_flags = <optimized out>
        pick_next_process = <optimized out>

With AI's help, dump of the local variables of frame 5:

(gdb) frame 5
#5  0x000000000085f914 in run_resource_dtor (vbin=0x7f420683d578) at beam/erl_nif.c:2981
2981    in beam/erl_nif.c
(gdb) info locals
msg_env = {env = {mod_nif = 0x1e4606c0, proc = 0x7f4273141878, hp = 0xc52160 <phony_heap>, hp_end = 0xc52160 <phony_heap>, heap_frag = 0x0, tmp_obj_list = 0x0, exception_thrown = 0, tracee = 0x0, exiting = 1546499616}, phony_proc = {common = {id = 18446744073709551603, refc = {
        atmc = {counter = 0}, sint = 0}, timer = {counter = 0}, u = {alive = {started_interval = 0, reg = 0x0, links = 0x0, lt_monitors = 0x0, monitors = 0x0}, release = {later = 0, func = 0x0, data = 0x0, next = 0x0}}, tracee = {all_trace_flags = 0, first_ref = 0x0}}, 
    htop = 0xc52160 <phony_heap>, stop = 0xc52178 <phony_heap+24>, frame_pointer = 0x0, freason = 0, fvalue = 0, fcalls = 0, flags = 0, rcount = 0, schedule_count = 0 '\000', arity = 0 '\000', max_arg_reg = 0 '\000', arg_reg = 0x0, def_arg_reg = {0, 0, 0, 0, 0, 0}, 
    heap = 0xc52160 <phony_heap>, hend = 0xc52178 <phony_heap+24>, abandoned_heap = 0x0, heap_sz = 0, min_heap_size = 0, min_vheap_size = 0, max_heap_size = 0, i = 0x0, catches = 0, return_trace_frames = 0, reds = 0, group_leader = 0, ftrace = 0, next = 0x0, uniq = 0, sig_qs = {
      first = 0x0, last = 0x0, save = 0x0, mq_len = 0, cont = 0x0, cont_last = 0x0, nmsigs = {next = 0x0, last = 0x0}, mlenoffs = 0, recv_mrk_blk = 0x0, flags = 0}, bif_timers = 0x0, dictionary = 0x0, seq_trace_clock = 0, seq_trace_lastcnt = 0, seq_trace_token = 0, u = {
      real_proc = 0x0, terminate = 0x0, initial = {module = 0, function = 0, arity = 0}}, current = 0x0, parent = 0, static_flags = 0, gen_gcs = 0, max_gen_gcs = 0, high_water = 0x0, old_hend = 0x0, old_htop = 0x0, old_heap = 0x0, off_heap = {first = 0x0, overhead = 0}, 
    wrt_bins = 0x0, mbuf = 0x0, live_hf_end = 0x0, msg_frag = 0x0, mbuf_sz = 0, psd = {counter = 0}, bin_vheap_sz = 0, bin_old_vheap_sz = 0, bin_old_vheap = 0, sys_task_qs = 0x0, dirty_sys_tasks = 0x0, state = {counter = 0}, xstate = {counter = 0}, 
    sig_inq_contention_counter = 0, sig_inq = {first = 0x0, last = 0x0, mlenoffs = 0, nmsigs = {next = 0x0, last = 0x0}}, sig_inq_buffers = {counter = 0}, trace_msg_q = 0x0, lock = {flags = {counter = 0}, queue = {0x0, 0x0, 0x0, 0x0, 0x0}}, scheduler_data = 0x0, run_queue = {
      counter = 0}}}
bin = 0x7f420683d578
resource = 0x7f420683d5b0
type = 0x1e462860
(gdb) p * resource
$3 = {type = 0x1e462860, monitors = 0x0, data = " "}
(gdb) p * bin
$4 = {intern = {flags = 1, apparent_size = 24, refc = {counter = 0}}, orig_size = 48, orig_bytes = "\240"}
(gdb) p * type
$5 = {next = 0x1e4628f8, prev = 0xc52060 <resource_type_list>, owner = 0x1e4606c0, fn = {dtor = 0x7f4272a94090 <mac_context_dtor>, stop = 0x0, down = 0x0, members = 0, dyncall = 0x0}, fn_real = {dtor = 0x7f4272a94090 <mac_context_dtor>, stop = 0x0, down = 0x0, members = 0, 
    dyncall = 0x0}, refc = {counter = 201}, module = 478347, name = 1677835}
(gdb) x/4gx &resource->data[0]
0x7f420683d5c0: 0x00007f425cadb720      0x86ce90e95eceffc0
0x7f420683d5d0: 0xb2ab5a3ab486e129      0xcb64d688c38c0bcf
(gdb) x/4gx 0x00007f425cadb720
0x7f425cadb720: 0x00007f425c54c230  

Could it be a bug of OTP-27 or compatibility issue with OpenSSL 3.5.1?
Please help analyze the issue, thanks.

I have the coredump file saved, please let me know if more info is needed.

environment:

• Ubuntu 22.04.5 LTS + containerd + UBI9
• OpenSSL 3.5.1
• glibc: 2.34

[sverker]

I think this is a solved bug in OTP crypto with a fix #9119 released in OTP 28.0 but for some reason not on 27.

I pushed a backported commit on OTP-27.3.4.6 if you want to try out the fix on 27.
https://github.com/sverker/otp/tree/sverker/crypto/EVP_MAC-double-free

If I'm correct the root cause is a wrap-around of a signed 32-bit counter (by EVP_MAC_fetch) which would take ~2 billion calls to crypto:mac_init before it happens. How far apart in time are these double free's?

[fpxu]

Thank you, I'll try the fix.

[fpxu]

@sverker
It happens 1 or 2 times every 24 hours in one specific environment(Ubuntu 22.04.5 LTS). However it did not happen for more than 1 month in the other environment(Amazon Linux 2023). Containerd, container image, OpenSSL, glibc are all the same between these two environments.
Do you have any idea which part would causes the double free or wrap-around happen more frequently?

BTW, after the fix you provided, it didn't happen for about 48 hours in the environment that happened before.
Will the next patch release of OTP27 contain the backport fix?

[sverker]

I have put #10859 into the pipe for next OTP 27 patch release.

I can't say why your other environment do not experience the double free. As I said, it seems to take ~2 billion calls to the Erlang function crypto:mac_init before the counter wraps around.