[CRASH] 3.1.GIT and 3.2.GIT related to TRACE->HEP (clean_msg_clone, clean_hdr_field, relay_reply)

[gmaruzz]

core from a 3.1.latest from git, compiled deb packages, on a Buster machine, all packages fully updated

I use clustering in active/passive, and a lot of presence, pua, dialoginfo, etc

# gdb /usr/sbin/opensips ./core.opensips.123595.lb01.1657892645


#0  __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120
No locals.
#1  0x00007f25147329ef in _IO_vfprintf_internal (s=s@entry=0x5630846d8da0, format=format@entry=0x563084319368 "CRITICAL:core:%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n", ap=0x7ffdaf30a220) at vfprintf.c:1638
        len = 
        string_malloced = 0
        step0_jumps = {0, 3637, 3213, 3109, 4653, 2997, 4437, 4037, 3717, 4869, 4773, 3397, 4557, 4549, 3589, 4981, 3701, 4757, 3317, 2021, 1429, 1221, 2261, 1701, 1653, 797, 1773, 437, 437, 4333}
        space = 0
        is_short = 0
        use_outdigits = 0
        outc = 
        step1_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 4869, 4773, 3397, 4557, 4549, 3589, 4981, 3701, 4757, 3317, 2021, 1429, 1221, 2261, 1701, 1653, 797, 1773, 437, 437, 0}
        group = 0
        prec = 
        step2_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4773, 3397, 4557, 4549, 3589, 4981, 3701, 4757, 3317, 2021, 1429, 1221, 2261, 1701, 1653, 797, 1773, 437, 437, 0}
        string = 0x3 
        left = 0
        is_long_double = 
        width = 0
        signed_number = 
        step3a_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 3493, 0, 0, 0, 3589, 4981, 3701, 4757, 3317, 0, 0, 0, 0, 1701, 0, 0, 0, 0, 0, 0}
        alt = 0
        showsign = 0
        is_long = 
        is_char = 
        pad = 32 ' '
        step3b_jumps = {0 , 4557, 0, 0, 3589, 4981, 3701, 4757, 3317, 2021, 1429, 1221, 2261, 1701, 1653, 797, 1773, 0, 0, 0}
        step4_jumps = {0 , 3589, 4981, 3701, 4757, 3317, 2021, 1429, 1221, 2261, 1701, 1653, 797, 1773, 0, 0, 0}
        args_value = 
        is_negative = 
        number = 
        base = 
        the_arg = {pa_wchar = 0 L'\000', pa_int = 0, pa_long_int = 0, pa_long_long_int = 0, pa_u_int = 0, pa_u_long_int = 0, pa_u_long_long_int = 0, pa_double = 0, pa_long_double = , pa_string = 0x0, pa_wstring = 0x0, pa_pointer = 0x0, pa_user = 0x0}
        spec = 115 's'
        _buffer = {__routine = 0x7f2510b21a08, __arg = 0x5630000000a2, __canceltype = -1355768288, __prev = 0x7ffdaf309d20}
        _avail = 
        thousands_sep = 0x0
        grouping = 0xffffffffffffffff 
        done = 3042
        f = 0x5630843193b2 "s(%ld) - aborting!\n"
        lead_str_end = 0x563084319376 "%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n"
        end_of_spec = 
        work_buffer = "HC\247\020%\177\000\000\250C\247\020%\177\000\000\bD\247\020%\177\000\000v0M\204\060V\000\000$\000\000\000\000\000\000\000'L\"\204\060V\000\000\r\000\000\000\000\000\000\000'L\"\204\060V\000\000\n\000\000\000\000\000\000\000\331P\"\204\060V", '\000' , "Ɣ\262\252s\242]\321\002\0
00\000\000\000\000\000\000Ɣ\262\252s\242]@\303n\020%\177\000\000\000\000\000\000\000\000\000\000`$\317\374$\177\000\000\060:O\204\060V\000\000(:O\204\060V\000\000hg\257\020%\177\000\000\000\000\000\000\000\000\000\000L\003\316\374$\177", '\000' , "`j\235\020%\177\000\000\000Ɣ"...
        workstart = 0x0
        workend = 
        ap_save = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7ffdaf30a300, reg_save_area = 0x7ffdaf30a240}}
        nspecs_done = 4
        save_errno = 0
        readonly_format = 0
        __PRETTY_FUNCTION__ = "_IO_vfprintf_internal"
        __result = 
#2  0x00007f25147e9168 in ___vfprintf_chk (fp=fp@entry=0x5630846d8da0, flag=flag@entry=1, format=format@entry=0x563084319368 "CRITICAL:core:%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n", ap=ap@entry=0x7ffdaf30a220) at vfprintf_chk.c:33
        _IO_acquire_lock_file = 0x5630846d8da0
        done = 
#3  0x00007f25147d4307 in __GI___vsyslog_chk (pri=, flag=1, fmt=, ap=0x7ffdaf30a220) at ../misc/syslog.c:222
        now_tm = {tm_sec = 5, tm_min = 44, tm_hour = 13, tm_mday = 15, tm_mon = 6, tm_year = 122, tm_wday = 5, tm_yday = 195, tm_isdst = 0, tm_gmtoff = 0, tm_zone = 0x5630846f27d0 "UTC"}
        now = 1657892645
        fd = 
        f = 0x5630846d8da0
        buf = 0x0
        bufsize = 0
        msgoff = 21
        saved_errno = 0
        failbuf = "7\v\224\020%\177", '\000' , "\331P\"\204\060"
        clarg = 
#4  0x00007f25147d482f in __syslog_chk (pri=, flag=flag@entry=1, fmt=fmt@entry=0x563084319368 "CRITICAL:core:%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n") at ../misc/syslog.c:129
        ap = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7ffdaf30a310, reg_save_area = 0x7ffdaf30a240}}
#5  0x0000563084225413 in syslog (__fmt=0x563084319368 "CRITICAL:core:%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n", __pri=) at /usr/include/x86_64-linux-gnu/bits/syslog.h:31
No locals.
#6  fm_free (fm=, p=0x7f251085fec8, file=, func=, line=) at mem/f_malloc_dyn.h:237
        f = 0x7f251085fe98
        n = 
        __FUNCTION__ = "fm_free"
#7  0x0000563084251765 in clean_hdr_field (hf=hf@entry=0x7f25021258d0) at parser/hf.c:202
        __FUNCTION__ = "clean_hdr_field"
#8  0x00007f24fd2ef118 in clean_msg_clone (msg=0x7f2502124820, max=0x7f2502126068, min=0x7f2502124820) at sip_msg.h:100
        hdr = 0x7f25021258d0
        hdr = 
        __FUNCTION__ = "clean_msg_clone"
#9  run_trans_callbacks_locked (type=type@entry=128, trans=trans@entry=0x7f2501685540, req=, rpl=rpl@entry=0x7f25109d6a60, code=code@entry=200) at t_hooks.c:265
No locals.
#10 0x00007f24fd2ba3e2 in relay_reply (t=0x7f2501685540, p_msg=, branch=, msg_status=, cancel_bitmap=) at t_reply.c:1381
        relay = 0
        save_clone = 0
        buf = 0x7f25109407c0 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 172.16.20.201;received=172.16.20.201;rport=5060;branch=z9hG4bK624vN63BFXt9r\r\nFrom: \"KENNETH RICH\" ;tag=2Qr3Dv17yt6ZH\r\nTo: 
        uas_rb = 0x7f2501685640
        cb_s = {s = 0x7f25109407c0 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 172.16.20.201;received=172.16.20.201;rport=5060;branch=z9hG4bK624vN63BFXt9r\r\nFrom: \"KENNETH RICH\" ;tag=2Qr3Dv17yt6ZH\r\nTo: 
        branch = 0
        reply_status = 
        timer = 0
        cancel_bitmap = 0
        uac = 0x7f2501685718
        t = 0x7f2501685540
        backup_list = 
        has_reply_route = 
        old_route_type = 
        __FUNCTION__ = "reply_received"
#12 0x00005630841a6eb8 in forward_reply (msg=msg@entry=0x7f25109d6a60) at forward.c:499
        new_buf = 0x0
        to = 0x0
        new_len = 0
        mod = 0x7f25106f10f8
        proto = 
        id = 0
        send_sock = 
        s = 
        len = 
        __FUNCTION__ = "forward_reply"
#13 0x000056308418b79f in receive_msg (buf=0x5630844d2f40  "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 66.151.243.43:5070;branch=z9hG4bKcbcc.81a2b454.0\r\nVia: SIP/2.0/UDP 172.16.20.201;received=172.16.20.201;rport=5060;branch=z9hG4bK624vN63BFXt9r\r\nFrom: \"KENNETH RICH\" , 
    rcv_info=rcv_info@entry=0x7ffdaf30a760, existing_context=existing_context@entry=0x0, msg_flags=msg_flags@entry=0) at receive.c:266
        ctx = 0x7f2510b158a8
        msg = 0x7f25109d6a60
        start = {tv_sec = 1, tv_usec = 139796843303162}
        rc = 3
        old_route_type = 4
        tmp = 
        in_buff = {s = 0x5630844d2f40  "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 66.151.243.43:5070;branch=z9hG4bKcbcc.81a2b454.0\r\nVia: SIP/2.0/UDP 172.16.20.201;received=172.16.20.201;rport=5060;branch=z9hG4bK624vN63BFXt9r\r\nFrom: \"KENNETH RICH\" , bytes_read=) at net/proto_udp/proto_udp.c:186
        ri = {src_ip = {af = 2, len = 4, u = {addrl = {6747082365847064017, 0}, addr32 = {111005137, 1570927530, 0, 0}, addr16 = {52689, 1693, 29610, 23970, 0, 0, 0, 0}, addr = "\321͝\006\252s\242]\000\000\000\000\000\000\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {737384258, 0}, addr32 = {737384258, 0, 0, 0}, 
              addr16 = {38722, 11251, 0, 0, 0, 0, 0, 0}, addr = "B\227\363+", '\000' }}, src_port = 5060, dst_port = 5070, proto = 1, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023\304\321͝\006\000\000\000\000\000\000\000"}, sin = {sin_family = 2, 
              sin_port = 50195, sin_addr = {s_addr = 111005137}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 111005137, sin6_addr = {__in6_u = {__u6_addr8 = "\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000", __u6_addr16 = {0, 0, 0, 0, 1, 0, 0, 
                    0}, __u6_addr32 = {0, 0, 1, 0}}}, sin6_scope_id = 2939828149}}, bind_address = 0x7f25106e9280}
        len = 
        buf = "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 66.151.243.43:5070;branch=z9hG4bKcbcc.81a2b454.0\r\nVia: SIP/2.0/UDP 172.16.20.201;received=172.16.20.201;rport=5060;branch=z9hG4bK624vN63BFXt9r\r\nFrom: \"KENNETH RICH\" 
        fromlen = 16
        p = 
        msg = {s = 0x5630844d2f40  "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 66.151.243.43:5070;branch=z9hG4bKcbcc.81a2b454.0\r\nVia: SIP/2.0/UDP 172.16.20.201;received=172.16.20.201;rport=5060;branch=z9hG4bK624vN63BFXt9r\r\nFrom: \"KENNETH RICH\" , event_type=, fm=) at net/net_udp.c:278
        n = 
        read = 22064
        n = 
        read = 
        __FUNCTION__ = "handle_io"
#16 io_wait_loop_epoll (repeat=0, t=1, h=) at net/../io_wait_loop.h:311
        ret = 
        n = 
        r = 0
        i = 
        e = 0x7f2510b2e298
        ep_event = {events = 2216665448, data = {ptr = 0x106e928000005600, fd = 22016, u32 = 22016, u64 = 1184044830498510336}}
        fd = 
        curr_time = 1828
        __FUNCTION__ = "io_wait_loop_epoll"
#17 0x00005630842c45c6 in udp_start_processes (chd_rank=chd_rank@entry=0x5630844bd488 , startup_done=startup_done@entry=0x0) at net/net_udp.c:503
        si = 
        p_id = 
        i = 
        p = 
        __FUNCTION__ = "udp_start_processes"
#18 0x0000563084158973 in main_loop () at main.c:802
        startup_done = 0x0
        last_check = 0
        rc = 
        chd_rank = 11
        startup_done = 
        last_check = 
        rc = 
        __FUNCTION__ = "main_loop"
#19 main (argc=, argv=) at main.c:1491
        c = 
        r = 
        tmp = 0x7ffdaf30bec6 ""
        tmp_len = 
        port = 
        proto = 
        protos_no = 
        options = 0x563084310d20 "f:cCm:M:b:l:n:N:rRvdDFEVhw:t:u:g:p:P:G:W:o:a:k:s:"
        seed = 2580610176
        rfd = 
        __FUNCTION__ = "main"
(gdb) 

[gmaruzz]

(I have even other cores, if needed I can bt full them too)

maybe the problem is something related to trace to 2 trace_destinations?
or maybe to trace Dialog / Transaction mixed?

[gmaruzz]

I believe crashes I had are in some way connected to trace()->hep
I commented out ALL trace() from script, and no more crashes
It was crashing even with just one trace(D)->hep only on INVITEs
Maybe the updated libraries on Debian 10.12 latest fully updated have introduced/revealed a bug?

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[gmaruzz]

bump

[vladpaiu]

Hello,

Running into the same issue here, with 3.3 as well. Had the same core files as above.

Had OpenSIPS running with the DBG mem allocator, pasting further core information below :

SYSLOG : Aug 3 15:23:47 ip-10-220-24-102 /usr/sbin/opensips[61912]: CRITICAL:core:qm_debug_frag: qm_*: fragm. 0x7f8f461be6c8 (address 0x7f8f461be6f8) end overwritten(7f8f461be958, 0)!

CORE : #2 0x000055d0cc8909d1 in qm_debug_frag (qm=qm@entry=0x7f8f45cb5000, f=f@entry=0x7f8f461be6c8) at mem/q_malloc.c:114
#3 0x000055d0cc891175 in qm_malloc_dbg (qm=0x7f8f45cb5000, size=528, file=0x55d0cc9e9fe2 "net/net_tcp.c", func=0x55d0cc9ebda0 <FUNCTION.30> "tcpconn_new", line=894)
at mem/q_malloc_dyn.h:124
#4 0x000055d0cc921d7c in shm_malloc (size=528, function=function@entry=0x55d0cc9ebda0 <FUNCTION_.30> "tcpconn_new", line=line@entry=894,
file=0x55d0cc9e9fe2 "net/net_tcp.c") at net/../mem/shm_mem.h:312
#5 0x000055d0cc922f7b in tcpconn_new (sock=sock@entry=106, su=su@entry=0x7ffd8e17cce0, si=si@entry=0x7f8f49cedf80, prof=prof@entry=0x7ffd8e17cd00, state=state@entry=0,
flags=flags@entry=4) at net/net_tcp.c:894

#2 0x000055d0cc8909d1 in qm_debug_frag (qm=qm@entry=0x7f8f45cb5000, f=f@entry=0x7f8f461be6c8) at mem/q_malloc.c:114
114 in mem/q_malloc.c
(gdb) p *f
$9 = {size = 576, u = {nxt_free = 0x7f8f45cb6d80, is_free = 140253328010624}, file = 0x7f8f44d2f030 "tracer.c",
func = 0x7f8f44d325a0 <FUNCTION.50> "free_trace_info_shm", line = 1368, check = 17361641481138401520}

[gmaruzz]

it may be related to some library changes...

I've noticed that if you use sngrep with -L option (eg, listening for HEP), and add a bpf (eg: "portrange 5050-5090") sngrep is prone to crashes... (even if recompiled from sources)

probably the HEP code is similar in sngrep and opensips...

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.