Crash in 7.5.2.2

[SipSeb]

Hi,

we updated our rtpengines to 7.5.2.2 on Debian Buster last month, today one of the instances crashed.

Version:

ngcp-rtpengine-daemon:
  Installed: 7.5.2.2+0~mr7.5.2.2
  Candidate: 7.5.2.2+0~mr7.5.2.2
  Version table:
 *** 7.5.2.2+0~mr7.5.2.2 580
        500 https://deb.sipwise.com/spce/mr7.5.2 buster/main amd64 Packages
        100 /var/lib/dpkg/status

Coredump Output:

[Current thread is 1 (Thread 0x7f02c0ff9700 (LWP 1292))]
(gdb) bt full
#0  0x00007f02ef7507bb in raise () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1  0x00007f02ef73b535 in abort () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#2  0x00007f02ef73b40f in ?? () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#3  0x00007f02ef749102 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#4  0x0000558f0456114d in __make_transcoder (handler=handler@entry=0x7f028c115050, dest=dest@entry=0x7f029813fb50, output_transcoders=output_transcoders@entry=0x7f029c1d2b00, dtmf_payload_type=dtmf_payload_type@entry=-1) at codec.c:208
        __PRETTY_FUNCTION__ = "__make_transcoder"
        output_handler = <optimized out>
#5  0x0000558f045623e8 in codec_handlers_update (receiver=receiver@entry=0x7f02c413eb00, sink=sink@entry=0x7f0298210cc0, flags=flags@entry=0x7f02c0fe7600) at codec.c:619
        pt = 0x7f02941134b0
        dest_pt = 0x7f029813fb50
        handler = 0x7f028c115050
        dest_codecs = <optimized out>
        reverse_pt = <optimized out>
        l = 0x7f02d5a2dc20
        passthrough_handlers = 0x7f02b40014b0
        pref_dest_codec = <optimized out>
        sink_transcoding = <optimized out>
        dtmf_sinks = <optimized out>
        dtmf_payload_type = -1
        output_transcoders = 0x7f029c1d2b00
        transcode_dtmf = 0
#6  0x0000558f04527073 in monologue_offer_answer (other_ml=other_ml@entry=0x7f02940d9be0, streams=streams@entry=0x7f02c0fe75e0, flags=flags@entry=0x7f02c0fe7600) at call.c:1918
        sp = <optimized out>
        media_iter = <optimized out>
        ml_media = 0x7f02d59e7ce0
        other_ml_media = 0x7f02d5bfa260
        media = 0x7f02c413eb00
        other_media = <optimized out>
        num_ports = <optimized out>
        monologue = <optimized out>
        em = <optimized out>
        call = <optimized out>
#7  0x0000558f045448be in call_offer_answer_ng (input=input@entry=0x7f029c0fa5c8, output=output@entry=0x7f029c0fa568, opmode=opmode@entry=OP_ANSWER, addr=addr@entry=0x0, sin=sin@entry=0x0) at call_interfaces.strhash.c:1222
        sdp = {
          s = 0x7f02c0fe7a38 "v=0\r\no=Zoiper 0 1 IN IP4 192.168.178.45\r\ns=Z\r\nc=IN IP4 90.187.124.1\r\nt=0 0\r\nm=audio 38872 RTP/AVP 8 106 9 3 111 0 97 102 110 112 101 98 100 99\r\na=rtpmap:106 opus/48000/2\r\na=fmtp:106 minptime=20; usein"..., len = 625}
        errstr = 0x558f04575740 "Invalid dialogue association"
        parsed = {head = 0x7f02d5b23ae0, tail = 0x7f02d5b23ae0, length = 1}
        streams = {head = 0x7f02d59bc380, tail = 0x7f02d59bc380, length = 1}
        call = 0x7f02ac1ba640
        monologue = 0x7f02940d9be0
        ret = <optimized out>
        flags = {opmode = OP_ANSWER, call_id = {s = 0x7f02c0fe7cdb "16a141ce27eeb64b538693ce449ee5fe@domain.de13:received-froml3:IP413:217.10.xx.xxxe8:from-tag10:as250d66006:to-tag8:a53f78787:command6:answere", len = 43}, from_tag = {
            s = 0x7f02c0fe7d4e "a53f78787:command6:answere", len = 8}, to_tag = {s = 0x7f02c0fe7d3a "as250d66006:to-tag8:a53f78787:command6:answere", len = 10}, via_branch = {s = 0x0, len = 0}, received_from_family = {
            s = 0x7f02c0fe7d19 "IP413:217.10.xx.xxxe8:from-tag10:as250d66006:to-tag8:a53f78787:command6:answere", len = 3}, received_from_address = {
            s = 0x7f02c0fe7d1f "217.10.xx.xxxe8:from-tag10:as250d66006:to-tag8:a53f78787:command6:answere", len = 13}, media_address = {s = 0x0, len = 0}, transport_protocol_str = {s = 0x0, len = 0}, address_family_str = {s = 0x0,
            len = 0}, transport_protocol = 0x0, parsed_received_from = {family = 0x0, u = {ipv4 = {s_addr = 0}, ipv6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0,
                    0}}}}}, parsed_media_address = {family = 0x0, u = {ipv4 = {s_addr = 0}, ipv6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}}}, direction = {{
              s = 0x0, len = 0}, {s = 0x0, len = 0}}, address_family = 0x0, tos = 256, record_call_str = {s = 0x0, len = 0}, metadata = {s = 0x0, len = 0}, label = {s = 0x0, len = 0}, address = {s = 0x0, len = 0}, xmlrpc_callback = {
            family = 0x0, u = {ipv4 = {s_addr = 0}, ipv6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}}}, codec_strip = 0x0, codec_offer = {head = 0x0,
            tail = 0x0, length = 0}, codec_transcode = {head = 0x0, tail = 0x0, length = 0}, codec_mask = 0x0, codec_set = 0x0, ptime = 0, rev_ptime = 0, sdes_no = 0x0, asymmetric = 0, no_redis_update = 0, unidirectional = 0,
--Type <RET> for more, q to quit, c to continue without paging--c
          trust_address = -1, port_latching = 0, replace_origin = 0, replace_sess_conn = 0, ice_remove = -1, ice_force = 0, ice_force_relay = 0, rtcp_mux_offer = 0, rtcp_mux_require = 0, rtcp_mux_demux = 0, rtcp_mux_accept = 0, rtcp_mux_reject = 0, no_rtcp_attr = 0, full_rtcp_attr = 0, generate_mid = 0, strict_source = 0, media_handover = 0, dtls_passive = -1, reset = 0, all = 0, fragment = 0, record_call = 0, loop_protect = 0, original_sendrecv = 0, always_transcode = 0, asymmetric_codecs = 0, supports_load_limit = 0, dtls_off = 0, sdes_off = 0, sdes_unencrypted_srtp = 0, sdes_unencrypted_srtcp = 0, sdes_unauthenticated_srtp = 0, sdes_encrypted_srtp = 0, sdes_encrypted_srtcp = 0, sdes_authenticated_srtp = 0, pad_crypto = 0}
        chopper = 0x7f02d5a3d000
        recording = <optimized out>
#8  0x0000558f04547b1f in call_answer_ng (input=input@entry=0x7f029c0fa5c8, output=output@entry=0x7f029c0fa568) at call_interfaces.strhash.c:1279
No locals.
#9  0x0000558f04537209 in control_ng_incoming (obj=0x558f04d70070, buf=<optimized out>, sin=0x7f02c0fe79c0, addr=<optimized out>, ul=<optimized out>) at control_ng.strhash.c:350
        c = 0x558f04d70070
        bencbuf = {pieces = 0x7f029c194830, free_list = 0x7f029c1949e0, error = 0}
        dict = <optimized out>
        resp = 0x7f029c0fa568
        cmd = <optimized out>
        cookie = {s = 0x7f02c0fe7a20 "0_1211_384161", len = 13}
        data = <optimized out>
        reply = {s = 0x7f02c0fe7840 "ȥ\017\234\002\177", len = -1098524672}
        to_send = 0x0
        callid = {s = 0x7f02c0fe7cdb "16a141ce27eeb64b538693ce449ee5fe@domain.de13:received-froml3:IP413:217.10.xx.xxxe8:from-tag10:as250d66006:to-tag8:a53f78787:command6:answere", len = 43}
        errstr = 0x0
        resultstr = 0x558f045732ca "ok"
        iov = {{iov_base = 0x7f02c0fe7a20, iov_len = 14}, {iov_base = 0x558f04571527, iov_len = 1}, {iov_base = 0x7f029c0775b4, iov_len = 13190406733186848768}}
        iovlen = <optimized out>
        log_str = <optimized out>
        cmd_start = {tv_sec = 1578052075, tv_usec = 782510}
        cmd_stop = {tv_sec = 94072749820672, tv_usec = 139649804565024}
        cmd_process_time = {tv_sec = 840, tv_usec = 139650584940458}
        cur = <optimized out>
        ret = <optimized out>
        __PRETTY_FUNCTION__ = "control_ng_incoming"
        cmdcode = 2
#10 0x0000558f0453612e in udp_listener_incoming (fd=<optimized out>, p=0x558f04d60b00, x=<optimized out>) at udp_listener.c:54
        cb = 0x558f04d60b00
        len = <optimized out>
        buf = "0_1211_384161\000d3:sdp625:v=0\r\no=Zoiper 0 1 IN IP4 192.168.178.45\r\ns=Z\r\nc=IN IP4 90.187.124.1\r\nt=0 0\r\nm=audio 38872 RTP/AVP 8 106 9 3 111 0 97 102 110 112 101 98 100 99\r\na=rtpmap:106 opus/48000/2\r\na=fmt"...
        addr = "217.10.xx.xx:49028", '\000' <repeats 45 times>
        str = {s = 0x7f02c0fe7a20 "0_1211_384161", len = 840}
        listener = 0x558f04d70108
        sin = {address = {family = 0x558f04591860 <__socket_families>, u = {ipv4 = {s_addr = 775949017}, ipv6 = {__in6_u = {__u6_addr8 = "\331\n@.", '\000' <repeats 11 times>, __u6_addr16 = {2777, 11840, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {775949017, 0, 0, 0}}}}}, port = 49028}
#11 0x0000558f04523393 in poller_poll (p=0x558f04d6fd10, timeout=<optimized out>) at poller.c:351
        ret = 1
        i = <optimized out>
        it = 0x558f04d69de0
        evs = {{events = 1, data = {ptr = 0x6, fd = 6, u32 = 6, u64 = 6}}, {events = 1, data = {ptr = 0x6, fd = 6, u32 = 6, u64 = 6}}, {events = 1, data = {ptr = 0x309, fd = 777, u32 = 777, u64 = 777}}, {events = 1, data = {ptr = 0x2de, fd = 734, u32 = 734, u64 = 734}}, {events = 1, data = {ptr = 0xcd, fd = 205, u32 = 205, u64 = 205}}, {events = 1, data = {ptr = 0x609, fd = 1545, u32 = 1545, u64 = 1545}}, {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}} <repeats 87 times>, {events = 0, data = {ptr = 0x420, fd = 1056, u32 = 1056, u64 = 1056}}, {events = 0, data = {ptr = 0x700000000, fd = 0, u32 = 0, u64 = 30064771072}}, {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}}, {events = 64, data = {ptr = 0x9c000ad800000000, fd = 0, u32 = 0, u64 = 11240996592745971712}}, {events = 32514, data = {ptr = 0x41f, fd = 1055, u32 = 1055, u64 = 1055}}, {events = 1104, data = {ptr = 0xfffffcf800000000, fd = 0, u32 = 0, u64 = 18446740740814929920}}, {events = 4294967295, data = {ptr = 0x10, fd = 16, u32 = 16, u64 = 16}}, {events = 67, data = {ptr = 0x200000040, fd = 64, u32 = 64, u64 = 8589934656}}, {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}}, {events = 93, data = {ptr = 0x7c0000006e, fd = 110, u32 = 110, u64 = 532575944814}}, {events = 119, data = {ptr = 0xb70dbd09be85d800, fd = -1098524672, u32 = 3196442624, u64 = 13190406733186848768}}, {events = 0, data = {ptr = 0x20500000000, fd = 0, u32 = 0, u64 = 2220498092032}}, {events = 0, data = {ptr = 0x7f029c002600, fd = -1677711872, u32 = 2617255424, u64 = 139649183917568}}, {events = 512, data = {ptr = 0x9c0025f000000000, fd = 0, u32 = 0, u64 = 11241026382639136768}}, {events = 32514, data = {ptr = 0x7f029c000020, fd = -1677721568, u32 = 2617245728, u64 = 139649183907872}}, {events = 624, data = {ptr = 0xef79c7a500000000, fd = 0, u32 = 0, u64 = 17256042958730297344}}, {events = 32514, data = {ptr = 0x7f029c0019f0, fd = -1677714960, u32 = 2617252336, u64 = 139649183914480}}, {events = 512, data = {ptr = 0x1f000000000, fd = 0, u32 = 0, u64 = 2130303778816}}, {events = 0, data = {ptr = 0x7f029c000020, fd = -1677721568, u32 = 2617245728, u64 = 139649183907872}}, {events = 1, data = {ptr = 0x4d0f1d800000000, fd = 0, u32 = 0, u64 = 347043081322758144}}, {events = 21903, data = {ptr = 0x7f02a8002a80, fd = -1476384128, u32 = 2818583168, u64 = 139649385245312}}, {events = 4017739866, data = {ptr = 0xc0ff802000007f02, fd = 32514, u32 = 32514, u64 = 13906975049270722306}}, {events = 32514, data = {ptr = 0x8, fd = 8, u32 = 8, u64 = 8}}, {events = 32, data = {ptr = 0xef79edc800000000, fd = 0, u32 = 0, u64 = 17256084890496008192}}, {events = 32514, data = {ptr = 0x200, fd = 512, u32 = 512, u64 = 512}}, {events = 4077551927, data = {ptr = 0x9c00260000007f02, fd = 32514, u32 = 32514, u64 = 11241026451358646018}}, {events = 32514, data = {ptr = 0xb70dbd09be85d800, fd = -1098524672, u32 = 3196442624, u64 = 13190406733186848768}}, {events = 256, data = {ptr = 0x3300000000, fd = 0, u32 = 0, u64 = 219043332096}}, {events = 0, data = {ptr = 0x7f029c000b40, fd = -1677718720, u32 = 2617248576, u64 = 139649183910720}}, {events = 24, data = {ptr = 0x9c000b2000000000, fd = 0, u32 = 0, u64 = 11240996901983617024}}, {events = 32514, data = {ptr = 0x10, fd = 16, u32 = 16, u64 = 16}}, {events = 2818583168, data = {ptr = 0xf30a8e5000007f02, fd = 32514, u32 = 32514, u64 = 17512966575232155394}}, {events = 32514, data = {ptr = 0x7f029c000b20, fd = -1677718752, u32 = 2617248544, u64 = 139649183910688}}, {events = 2617255776, data = {ptr = 0x2000007f02, fd = 32514, u32 = 32514, u64 = 137438985986}}, {events = 0, data = {ptr = 0x33, fd = 51, u32 = 51, u64 = 51}}}
        ev = <optimized out>
        e = {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}}
#12 0x0000558f0452380d in poller_loop (d=0x558f04d6fd10) at poller.c:508
        p = 0x558f04d6fd10
#13 0x0000558f04523922 in thread_detach_func (d=0x558f04d6eba0) at aux.c:207
        dt = 0x558f04d6eba0
        t = 0x7f02a8001ab0
        scheduler = <optimized out>
#14 0x00007f02ef8e1fa3 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
No symbol table info available.
#15 0x00007f02ef8124cf in clone () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.

Can you see a cause for this crash?

[rfuchs]

Hm, failed assertion, but the line number doesn't seem to match the code... Anyway, can you open the dump in gdb, execute and post the output of:

frame 4
p *handler
p *dest
up
p *pt
p *dest_pt
p *handler

[SipSeb]

Sure.

(gdb) frame 4
#4  0x0000558f0456114d in __make_transcoder (handler=handler@entry=0x7f028c115050, dest=dest@entry=0x7f029813fb50, output_transcoders=output_transcoders@entry=0x7f029c1d2b00, dtmf_payload_type=dtmf_payload_type@entry=-1) at codec.c:208
208	codec.c: No such file or directory.
(gdb) p *handler
$1 = {source_pt = {payload_type = 112, encoding_with_params = {s = 0x7f02b4186e82 "G726-32/8000", len = 12}, encoding = {s = 0x7f02b4186e8f "G726-32", len = 7}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
    format_parameters = {s = 0x0, len = 0}, ptime = 30, bitrate = 0, codec_def = 0x0}, dest_pt = {payload_type = 112, encoding_with_params = {s = 0x7f02b4186e82 "G726-32/8000", len = 12}, encoding = {s = 0x7f02b4186e8f "G726-32",
      len = 7}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1, format_parameters = {s = 0x0, len = 0}, ptime = 30, bitrate = 0, codec_def = 0x0}, dtmf_payload_type = -1,
  func = 0x558f04563150 <handler_func_passthrough>, kernelize = -1, transcoder = 0, dtmf_scaler = 0, ssrc_hash = 0x7f028410f630, output_handler = 0x7f028c115050, ssrc_handler = 0x0}
(gdb) p *dest
$2 = {payload_type = 111, encoding_with_params = {s = 0x7f029c216347 "speex/16000", len = 11}, encoding = {s = 0x7f029c216353 "speex", len = 5}, clock_rate = 16000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
  format_parameters = {s = 0x0, len = 0}, ptime = 20, bitrate = 0, codec_def = 0x558f04591df8 <__codec_defs+952>}
(gdb) up
#5  0x0000558f045623e8 in codec_handlers_update (receiver=receiver@entry=0x7f02c413eb00, sink=sink@entry=0x7f0298210cc0, flags=flags@entry=0x7f02c0fe7600) at codec.c:619
619	in codec.c
(gdb) p *pt
$3 = {payload_type = 112, encoding_with_params = {s = 0x7f029c2163a5 "speex/32000", len = 11}, encoding = {s = 0x7f029c2163b1 "speex", len = 5}, clock_rate = 32000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
  format_parameters = {s = 0x0, len = 0}, ptime = 30, bitrate = 0, codec_def = 0x558f04591df8 <__codec_defs+952>}
(gdb) p *dest_pt
$4 = {payload_type = 111, encoding_with_params = {s = 0x7f029c216347 "speex/16000", len = 11}, encoding = {s = 0x7f029c216353 "speex", len = 5}, clock_rate = 16000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
  format_parameters = {s = 0x0, len = 0}, ptime = 20, bitrate = 0, codec_def = 0x558f04591df8 <__codec_defs+952>}
(gdb) p *handler
$5 = {source_pt = {payload_type = 112, encoding_with_params = {s = 0x7f02b4186e82 "G726-32/8000", len = 12}, encoding = {s = 0x7f02b4186e8f "G726-32", len = 7}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
    format_parameters = {s = 0x0, len = 0}, ptime = 30, bitrate = 0, codec_def = 0x0}, dest_pt = {payload_type = 112, encoding_with_params = {s = 0x7f02b4186e82 "G726-32/8000", len = 12}, encoding = {s = 0x7f02b4186e8f "G726-32",
      len = 7}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1, format_parameters = {s = 0x0, len = 0}, ptime = 30, bitrate = 0, codec_def = 0x0}, dtmf_payload_type = -1,
  func = 0x558f04563150 <handler_func_passthrough>, kernelize = -1, transcoder = 0, dtmf_scaler = 0, ssrc_hash = 0x7f028410f630, output_handler = 0x7f028c115050, ssrc_handler = 0x0}

[SipSeb]

Another machine, same version, another crash:

Core was generated by `/usr/sbin/rtpengine --pidfile /var/run/ngcp-rtpengine-daemon.pid --config-file'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f20c0a857bb in raise () from /lib/x86_64-linux-gnu/libc.so.6
[Current thread is 1 (Thread 0x7f20737fe700 (LWP 1234))]
(gdb) bt full
#0  0x00007f20c0a857bb in raise () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1  0x00007f20c0a70535 in abort () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#2  0x00007f20c0a7040f in ?? () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#3  0x00007f20c0a7e102 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#4  0x000055dbeb86a14d in __make_transcoder (handler=handler@entry=0x7f20881a2c30, dest=dest@entry=0x7f20881b8a30, output_transcoders=output_transcoders@entry=0x7f20681f1aa0, dtmf_payload_type=dtmf_payload_type@entry=-1) at codec.c:208
        __PRETTY_FUNCTION__ = "__make_transcoder"
        output_handler = <optimized out>
#5  0x000055dbeb86b3e8 in codec_handlers_update (receiver=receiver@entry=0x7f20941a3970, sink=sink@entry=0x7f205c0ed040, flags=flags@entry=0x7f20737ec600) at codec.c:619
        pt = 0x7f2064182a30
        dest_pt = 0x7f20881b8a30
        handler = 0x7f20881a2c30
        dest_codecs = <optimized out>
        reverse_pt = <optimized out>
        l = 0x7f20a4059c20
        passthrough_handlers = 0x0
        pref_dest_codec = <optimized out>
        sink_transcoding = <optimized out>
        dtmf_sinks = <optimized out>
        dtmf_payload_type = -1
        output_transcoders = 0x7f20681f1aa0
        transcode_dtmf = 0
#6  0x000055dbeb830073 in monologue_offer_answer (other_ml=other_ml@entry=0x7f208c095bf0, streams=streams@entry=0x7f20737ec5e0, flags=flags@entry=0x7f20737ec600) at call.c:1918
        sp = <optimized out>
        media_iter = <optimized out>
        ml_media = 0x7f20a5893c60
        other_ml_media = 0x7f20a5304780
        media = 0x7f20941a3970
        other_media = <optimized out>
        num_ports = <optimized out>
        monologue = <optimized out>
        em = <optimized out>
        call = <optimized out>
#7  0x000055dbeb84d8be in call_offer_answer_ng (input=input@entry=0x7f205402c318, output=output@entry=0x7f205402c2b8, opmode=opmode@entry=OP_ANSWER, addr=addr@entry=0x0, sin=sin@entry=0x0) at call_interfaces.strhash.c:1222
        sdp = {
          s = 0x7f20737eca38 "v=0\r\no=2677846e0 14 2347 IN IP4 192.168.8.108\r\ns=Talk\r\nc=IN IP4 109.41.64.87\r\nt=0 0\r\na=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics\r\nm=audio 7206 RTP/AVP 96 97 98 0 8 18 101 "..., len = 582}
        errstr = 0x55dbeb87e740 "Invalid dialogue association"
        parsed = {head = 0x7f20a5346d60, tail = 0x7f20a5346d60, length = 1}
        streams = {head = 0x7f20a58b7b00, tail = 0x7f20a58b7b00, length = 1}
        call = 0x7f20841ded90
        monologue = 0x7f208c095bf0
        ret = <optimized out>
        flags = {opmode = OP_ANSWER, call_id = {s = 0x7f20737ecc97 "490ba90c6234e559571899d70e13322d@domain.de13:received-froml3:IP411:217.10.xx.xe8:from-tag10:as32a9eb096:to-tag7:7-58fGI7:command6:answere", len = 43}, from_tag = {
            s = 0x7f20737ecd08 "7-58fGI7:command6:answere", len = 7}, to_tag = {s = 0x7f20737eccf4 "as32a9eb096:to-tag7:7-58fGI7:command6:answere", len = 10}, via_branch = {s = 0x0, len = 0}, received_from_family = {
            s = 0x7f20737eccd5 "IP411:217.10.xx.xe8:from-tag10:as32a9eb096:to-tag7:7-58fGI7:command6:answere", len = 3}, received_from_address = {
            s = 0x7f20737eccdb "217.10.xx.xe8:from-tag10:as32a9eb096:to-tag7:7-58fGI7:command6:answere", len = 11}, media_address = {s = 0x0, len = 0}, transport_protocol_str = {s = 0x0, len = 0}, address_family_str = {s = 0x0,
            len = 0}, transport_protocol = 0x0, parsed_received_from = {family = 0x0, u = {ipv4 = {s_addr = 0}, ipv6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0,
                    0}}}}}, parsed_media_address = {family = 0x0, u = {ipv4 = {s_addr = 0}, ipv6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}}}, direction = {{
              s = 0x0, len = 0}, {s = 0x0, len = 0}}, address_family = 0x0, tos = 256, record_call_str = {s = 0x0, len = 0}, metadata = {s = 0x0, len = 0}, label = {s = 0x0, len = 0}, address = {s = 0x0, len = 0}, xmlrpc_callback = {
            family = 0x0, u = {ipv4 = {s_addr = 0}, ipv6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}}}, codec_strip = 0x0, codec_offer = {head = 0x0,
            tail = 0x0, length = 0}, codec_transcode = {head = 0x0, tail = 0x0, length = 0}, codec_mask = 0x0, codec_set = 0x0, ptime = 0, rev_ptime = 0, sdes_no = 0x0, asymmetric = 0, no_redis_update = 0, unidirectional = 0,
          trust_address = -1, port_latching = 0, replace_origin = 0, replace_sess_conn = 0, ice_remove = -1, ice_force = 0, ice_force_relay = 0, rtcp_mux_offer = 0, rtcp_mux_require = 0, rtcp_mux_demux = 0, rtcp_mux_accept = 0, rtcp_mux_reject = 0, no_rtcp_attr = 0, full_rtcp_attr = 0, generate_mid = 0, strict_source = 0, media_handover = 0, dtls_passive = -1, reset = 0, all = 0, fragment = 0, record_call = 0, loop_protect = 0, original_sendrecv = 0, always_transcode = 0, asymmetric_codecs = 0, supports_load_limit = 0, dtls_off = 0, sdes_off = 0, sdes_unencrypted_srtp = 0, sdes_unencrypted_srtcp = 0, sdes_unauthenticated_srtp = 0, sdes_encrypted_srtp = 0, sdes_encrypted_srtcp = 0, sdes_authenticated_srtp = 0, pad_crypto = 0}
        chopper = 0x7f20a54f9da0
        recording = <optimized out>
#8  0x000055dbeb850b1f in call_answer_ng (input=input@entry=0x7f205402c318, output=output@entry=0x7f205402c2b8) at call_interfaces.strhash.c:1279
No locals.
#9  0x000055dbeb840209 in control_ng_incoming (obj=0x55dbed4a4070, buf=<optimized out>, sin=0x7f20737ec9c0, addr=<optimized out>, ul=<optimized out>) at control_ng.strhash.c:350
        c = 0x55dbed4a4070
        bencbuf = {pieces = 0x7f20540b0600, free_list = 0x7f20540b0690, error = 0}
        dict = <optimized out>
        resp = 0x7f205402c2b8
        cmd = <optimized out>
        cookie = {s = 0x7f20737eca20 "0_41841_18845", len = 13}
        data = <optimized out>
        reply = {s = 0x7f20737ec840 "\030\303\002T \177", len = 2123955712}
        to_send = 0x0
        callid = {s = 0x7f20737ecc97 "490ba90c6234e559571899d70e13322d@domain.de13:received-froml3:IP411:217.10.xx.xe8:from-tag10:as32a9eb096:to-tag7:7-58fGI7:command6:answere", len = 43}
        errstr = 0x0
        resultstr = 0x55dbeb87c2ca "ok"
        iov = {{iov_base = 0x7f20737eca20, iov_len = 13}, {iov_base = 0x55dbeb87a527, iov_len = 1}, {iov_base = 0x7f2054160018, iov_len = 17523129178648018432}}
        iovlen = <optimized out>
        log_str = <optimized out>
        cmd_start = {tv_sec = 1578404768, tv_usec = 576950}
        cmd_stop = {tv_sec = 94403067202304, tv_usec = 139777353370144}
        cmd_process_time = {tv_sec = 769, tv_usec = 139778648793002}
        cur = <optimized out>
        ret = <optimized out>
        __PRETTY_FUNCTION__ = "control_ng_incoming"
        cmdcode = 2
#10 0x000055dbeb83f12e in udp_listener_incoming (fd=<optimized out>, p=0x55dbed494b00, x=<optimized out>) at udp_listener.c:54
        cb = 0x55dbed494b00
        len = <optimized out>
        buf = "0_41841_18845\000d3:sdp582:v=0\r\no=2677846e0 14 2347 IN IP4 192.168.8.108\r\ns=Talk\r\nc=IN IP4 109.41.64.87\r\nt=0 0\r\na=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics\r\nm=audio 7206 RTP/"...
        addr = "217.10.xx.xxx:56134", '\000' <repeats 44 times>
        str = {s = 0x7f20737eca20 "0_41841_18845", len = 769}
        listener = 0x55dbed4a4108
        sin = {address = {family = 0x55dbeb89a860 <__socket_families>, u = {ipv4 = {s_addr = 3930327769}, ipv6 = {__in6_u = {__u6_addr8 = "\331\nD\352", '\000' <repeats 11 times>, __u6_addr16 = {2777, 59972, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {3930327769, 0, 0, 0}}}}}, port = 56134}
#11 0x000055dbeb82c393 in poller_poll (p=0x55dbed4a3bd0, timeout=<optimized out>) at poller.c:351
        ret = 1
        i = <optimized out>
        it = 0x55dbed49dde0
        evs = {{events = 1, data = {ptr = 0x6, fd = 6, u32 = 6, u64 = 6}}, {events = 1, data = {ptr = 0x333, fd = 819, u32 = 819, u64 = 819}}, {events = 1, data = {ptr = 0x2e1, fd = 737, u32 = 737, u64 = 737}}, {events = 1, data = {ptr = 0x608, fd = 1544, u32 = 1544, u64 = 1544}}, {events = 1, data = {ptr = 0x21c, fd = 540, u32 = 540, u64 = 540}}, {events = 1, data = {ptr = 0x645, fd = 1605, u32 = 1605, u64 = 1605}}, {events = 1, data = {ptr = 0x7a, fd = 122, u32 = 122, u64 = 122}}, {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}} <repeats 86 times>, {events = 0, data = {ptr = 0x420, fd = 1056, u32 = 1056, u64 = 1056}}, {events = 0, data = {ptr = 0x700000000, fd = 0, u32 = 0, u64 = 30064771072}}, {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}}, {events = 64, data = {ptr = 0x54000ad800000000, fd = 0, u32 = 0, u64 = 6052849822015160320}}, {events = 32544, data = {ptr = 0x41f, fd = 1055, u32 = 1055, u64 = 1055}}, {events = 1104, data = {ptr = 0xfffffcf800000000, fd = 0, u32 = 0, u64 = 18446740740814929920}}, {events = 4294967295, data = {ptr = 0x10, fd = 16, u32 = 16, u64 = 16}}, {events = 67, data = {ptr = 0x200000040, fd = 64, u32 = 64, u64 = 8589934656}}, {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}}, {events = 93, data = {ptr = 0x7c0000006e, fd = 110, u32 = 110, u64 = 532575944814}}, {events = 119, data = {ptr = 0xf32ea9257e98fe00, fd = 2123955712, u32 = 2123955712, u64 = 17523129178648018432}}, {events = 0, data = {ptr = 0x20500000000, fd = 0, u32 = 0, u64 = 2220498092032}}, {events = 0, data = {ptr = 0x7f2054002a00, fd = 1409296896, u32 = 1409296896, u64 = 139776824977920}}, {events = 512, data = {ptr = 0x540029f000000000, fd = 0, u32 = 0, u64 = 6052884009954836480}}, {events = 32544, data = {ptr = 0x7f2054000020, fd = 1409286176, u32 = 1409286176, u64 = 139776824967200}}, {events = 672, data = {ptr = 0xc0ad17a500000000, fd = 0, u32 = 0, u64 = 13883779223690149888}}, {events = 32544, data = {ptr = 0x7f20540019f0, fd = 1409292784, u32 = 1409292784, u64 = 139776824973808}}, {events = 512, data = {ptr = 0x1f000000000, fd = 0, u32 = 0, u64 = 2130303778816}}, {events = 0, data = {ptr = 0x7f2054000020, fd = 1409286176, u32 = 1409286176, u64 = 139776824967200}}, {events = 1, data = {ptr = 0xed4431d800000000, fd = 0, u32 = 0, u64 = 17096844889187942400}}, {events = 21979, data = {ptr = 0x7f2060002ae0, fd = 1610623712, u32 = 1610623712, u64 = 139777026304736}}, {events = 3232573530, data = {ptr = 0x737fd02000007f20, fd = 32544, u32 = 32544, u64 = 8322599472261529376}}, {events = 32544, data = {ptr = 0x8, fd = 8, u32 = 8, u64 = 8}}, {events = 32, data = {ptr = 0xc0ad3dc800000000, fd = 0, u32 = 0, u64 = 13883821155455860736}}, {events = 32544, data = {ptr = 0x200, fd = 512, u32 = 512, u64 = 512}}, {events = 3292385591, data = {ptr = 0x54002a0000007f20, fd = 32544, u32 = 32544, u64 = 6052884078674345760}}, {events = 32544, data = {ptr = 0xf32ea9257e98fe00, fd = 2123955712, u32 = 2123955712, u64 = 17523129178648018432}}, {events = 256, data = {ptr = 0x3300000000, fd = 0, u32 = 0, u64 = 219043332096}}, {events = 0, data = {ptr = 0x7f2054000b40, fd = 1409289024, u32 = 1409289024, u64 = 139776824970048}}, {events = 24, data = {ptr = 0x54000b2000000000, fd = 0, u32 = 0, u64 = 6052850131252805632}}, {events = 32544, data = {ptr = 0x10, fd = 16, u32 = 16, u64 = 16}}, {events = 1610623712, data = {ptr = 0xc43dde5000007f20, fd = 32544, u32 = 32544, u64 = 14140702840192007968}}, {events = 32544, data = {ptr = 0x7f2054000b20, fd = 1409288992, u32 = 1409288992, u64 = 139776824970016}}, {events = 1409296896, data = {ptr = 0x2000007f20, fd = 32544, u32 = 32544, u64 = 137438986016}}, {events = 0, data = {ptr = 0x33, fd = 51, u32 = 51, u64 = 51}}}
        ev = <optimized out>
        e = {events = 0, data = {ptr = 0x0, fd = 0, u32 = 0, u64 = 0}}
#12 0x000055dbeb82c80d in poller_loop (d=0x55dbed4a3bd0) at poller.c:508
        p = 0x55dbed4a3bd0
#13 0x000055dbeb82c922 in thread_detach_func (d=0x55dbed4a2e60) at aux.c:207
        dt = 0x55dbed4a2e60
        t = 0x7f2060001a60
        scheduler = <optimized out>
#14 0x00007f20c0c16fa3 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
No symbol table info available.
#15 0x00007f20c0b474cf in clone () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.

And frame 4:

(gdb) frame 4
#4  0x000055dbeb86a14d in __make_transcoder (handler=handler@entry=0x7f20881a2c30, dest=dest@entry=0x7f20881b8a30, output_transcoders=output_transcoders@entry=0x7f20681f1aa0, dtmf_payload_type=dtmf_payload_type@entry=-1) at codec.c:208
208	codec.c: No such file or directory.
(gdb) p *handler
$1 = {source_pt = {payload_type = 97, encoding_with_params = {s = 0x7f208805d5d2 "iLBC/8000", len = 9}, encoding = {s = 0x7f208805d5dc "iLBC", len = 4}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
    format_parameters = {s = 0x7f208805d5e1 "mode=30", len = 7}, ptime = 30, bitrate = 0, codec_def = 0x0}, dest_pt = {payload_type = 97, encoding_with_params = {s = 0x7f208805d5d2 "iLBC/8000", len = 9}, encoding = {
      s = 0x7f208805d5dc "iLBC", len = 4}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1, format_parameters = {s = 0x7f208805d5e1 "mode=30", len = 7}, ptime = 30, bitrate = 0, codec_def = 0x0},
  dtmf_payload_type = -1, func = 0x55dbeb86c150 <handler_func_passthrough>, kernelize = -1, transcoder = 0, dtmf_scaler = 0, ssrc_hash = 0x7f206c1be010, output_handler = 0x7f20881a2c30, ssrc_handler = 0x0}
(gdb) p *dest
$2 = {payload_type = 97, encoding_with_params = {s = 0x7f20900bbc5e "speex/16000", len = 11}, encoding = {s = 0x7f20900bbc6a "speex", len = 5}, clock_rate = 16000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
  format_parameters = {s = 0x7f20900bbc70 "vbr=on", len = 6}, ptime = 20, bitrate = 0, codec_def = 0x55dbeb89adf8 <__codec_defs+952>}
(gdb) up
#5  0x000055dbeb86b3e8 in codec_handlers_update (receiver=receiver@entry=0x7f20941a3970, sink=sink@entry=0x7f205c0ed040, flags=flags@entry=0x7f20737ec600) at codec.c:619
619	in codec.c
(gdb) p *pt
$3 = {payload_type = 97, encoding_with_params = {s = 0x7f20900bbc5e "speex/16000", len = 11}, encoding = {s = 0x7f20900bbc6a "speex", len = 5}, clock_rate = 16000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
  format_parameters = {s = 0x7f20900bbc70 "vbr=on", len = 6}, ptime = 30, bitrate = 0, codec_def = 0x55dbeb89adf8 <__codec_defs+952>}
(gdb) p *dest_pt
$4 = {payload_type = 97, encoding_with_params = {s = 0x7f20900bbc5e "speex/16000", len = 11}, encoding = {s = 0x7f20900bbc6a "speex", len = 5}, clock_rate = 16000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
  format_parameters = {s = 0x7f20900bbc70 "vbr=on", len = 6}, ptime = 20, bitrate = 0, codec_def = 0x55dbeb89adf8 <__codec_defs+952>}
(gdb) p *handler
$5 = {source_pt = {payload_type = 97, encoding_with_params = {s = 0x7f208805d5d2 "iLBC/8000", len = 9}, encoding = {s = 0x7f208805d5dc "iLBC", len = 4}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1,
    format_parameters = {s = 0x7f208805d5e1 "mode=30", len = 7}, ptime = 30, bitrate = 0, codec_def = 0x0}, dest_pt = {payload_type = 97, encoding_with_params = {s = 0x7f208805d5d2 "iLBC/8000", len = 9}, encoding = {
      s = 0x7f208805d5dc "iLBC", len = 4}, clock_rate = 8000, encoding_parameters = {s = 0x0, len = 0}, channels = 1, format_parameters = {s = 0x7f208805d5e1 "mode=30", len = 7}, ptime = 30, bitrate = 0, codec_def = 0x0},
  dtmf_payload_type = -1, func = 0x55dbeb86c150 <handler_func_passthrough>, kernelize = -1, transcoder = 0, dtmf_scaler = 0, ssrc_hash = 0x7f206c1be010, output_handler = 0x7f20881a2c30, ssrc_handler = 0x0}

[rfuchs]

Can you tell if these are happening during a re-invite?

[rfuchs]

The commit above (64e56d7) should fix this

[SipSeb]

The only call-ID I could find was in frame number 7. And, oh wow, does this look weird.

First, these are the logs for this Call-ID:

Jan  7 14:44:39 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'offer' from 217.10.xx.xxx:36628
Jan  7 14:44:39 rtp22 rtpengine[1215]: NOTICE: [490ba90c6234e559571899d70e13322d@domain.de]: Creating new call
Jan  7 14:44:39 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'offer' from 217.10.xx.xxx:36628 (elapsed time 0.000473 sec)
Jan  7 14:44:39 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'offer' from 217.10.xx.xxx:36628
Jan  7 14:44:39 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'offer' from 217.10.xx.xxx:36628 (elapsed time 0.000147 sec)
Jan  7 14:44:58 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'answer' from 217.10.xx.xxx:49729
Jan  7 14:44:58 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'answer' from 217.10.xx.xxx:49729 (elapsed time 0.000225 sec)
Jan  7 14:45:02 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de port 26092]: Confirmed peer address as 212.9.xx.xxx:24912
Jan  7 14:45:02 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de port 25828]: Confirmed peer address as 109.41.64.87:18530
Jan  7 14:45:02 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de port 25828]: Kernelizing media stream: 109.41.64.87:18530
Jan  7 14:45:02 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de port 26092]: Kernelizing media stream: 212.9.xx.xxx:24912
Jan  7 14:45:03 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de port 26093]: Confirmed peer address as 212.9.xx.xxx:24913
Jan  7 14:45:07 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de port 25829]: Confirmed peer address as 109.41.64.87:22604
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'query' from 217.10.xx.xxx:38352
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'query' from 217.10.xx.xxx:38352 (elapsed time 0.000353 sec)
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'query' from 217.10.xx.xxx:38352
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'query' from 217.10.xx.xxx:38352 (elapsed time 0.000318 sec)
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'query' from 217.10.xx.xxx:38352
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'query' from 217.10.xx.xxx:38352 (elapsed time 0.000256 sec)
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'delete' from 217.10.xx.xxx:38352
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Scheduling deletion of call branch 'as32a9eb09' (via-branch '') in 30 seconds
Jan  7 14:45:43 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Replying to 'delete' from 217.10.xx.xxx:38352 (elapsed time 0.000376 sec)
Jan  7 14:46:08 rtp22 rtpengine[1215]: INFO: [490ba90c6234e559571899d70e13322d@domain.de]: Received command 'answer' from 217.10.xx.xxx:56134

I looked into the call flow for this call. This was an incoming call, going to one of our customers. There were two devices online, so the call was forked inside Kamailio and sent out to both devices. Now the "fun" part begins.

14:44:39 - INVITE sent out to both devices. Device 1 starts ringing, Device 2 doesn't react.
14:44:54 - Last retransmit to Device 2
14:44:58 - 200 OK on Device 1
14:45:43 - BYE on Device 1
14:45:54 - 100 Trying from Device 2
14:45:55 - 200 OK from Device 2. We just forward those Replies to the Originator, which ignores them, so there are some retransmits.
14:46:08 - reINVITE from Device 2 - CRASH!

Mind. Blown.

I can totally understand if this is something you never thought of. But can you still do something about the crash?

[SipSeb]

Wow, that was quick. So yes, it was a codec change, because it was a "device change".

Can you already tell, what package in your repository will contain that fix? We stopped building our own packages a while ago because our packages became unstable and the ones built by you didn't.

Thanks a lot.

[rfuchs]

This will be in the -daemon package. Do you want to test this patch separately first?

[SipSeb]

Actually I don't really know how to test it separately, since we use your packages and the error occurs so sporadically. But maybe I can build a sipp scenario for that.

My question actually should have been: What version of your packages will contain the fix?

[rfuchs]

Ok I'll push the patch out then. For the 7.5.2 branch, it will be 7.5.2.3.