search

OpenSIPS / opensips

OpenSIPS is a GPL implementation of a multi-functionality SIP Server that targets to deliver a high-level technical solution (performance, security and quality) to be used in professional SIP server platforms.
https://opensips.org
Other
1.28k stars 581 forks source link

[CRASH] Opensips 2.4.8 Segfault #2214

Closed Anthony-76 closed 4 years ago

Anthony-76 commented 4 years ago

Hi,

Opensips 2.4.8 installed on Debian 10 via apt source (installed on Proxmox - 12 CPU and 8GB of RAM)

flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
main.c compiled on  with gcc 8

Crash Core Dump

there is 2 dump file for the crash

https://drive.google.com/drive/folders/12xd9HcNenaZhqHGSrr2q6ZkSIK4zXg_A?usp=sharing

The result of bt full is:

(gdb) bt full
#0  0x000055b8447d8db3 in ?? ()
No symbol table info available.
#1  0x00007ffc42204010 in ?? ()
No symbol table info available.
#2  0x00000000000000b5 in ?? ()
No symbol table info available.
#3  0x00007ffc42204150 in ?? ()
No symbol table info available.
#4  0x764eab091cc39c00 in ?? ()
No symbol table info available.
#5  0x00007f1a31191ee0 in ?? ()
No symbol table info available.
#6  0x0000000000000000 in ?? ()

There is about 50 conccurents calls. The crash is random and I can't reproduce it. Opensips crash between 1 and 2 times by day

Relevant System Logs Aug 18 09:26:23 Opensips /usr/sbin/opensips[17102]: DELETE DANS bdd 3 (id,account) VALUES(7fb4fde52282a7b416934b407a08a641@xxxxx,sip:0xxxxxxx@xxxxxx) Aug 18 09:26:23 Opensips /usr/sbin/opensips[17102]: CRITICAL:core:sig_usr: segfault in process pid: 17102, id: 13 Aug 18 09:26:23 Opensips /usr/sbin/opensips[17103]: ERROR:nathelper:fix_nated_sdp_f: Unable to get bodies from message Aug 18 09:26:24 Opensips /usr/sbin/opensips[17125]: CRITICAL:core:handle_worker: dead child 13 (EOF received), pid 17102 Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips /usr/sbin/opensips[17089]: INFO:core:handle_sigs: child process 17102 exited by a signal 11 Aug 18 09:26:24 Opensips /usr/sbin/opensips[17089]: INFO:core:handle_sigs: core was generated Aug 18 09:26:24 Opensips /usr/sbin/opensips[17089]: INFO:core:handle_sigs: terminating due to SIGCHLD Aug 18 09:26:24 Opensips /usr/sbin/opensips[17092]: INFO:core:sig_usr: signal 15 received Aug 18 09:26:24 Opensips /usr/sbin/opensips[17090]: INFO:core:sig_usr: signal 15 received Aug 18 09:26:24 Opensips /usr/sbin/opensips[17093]: INFO:core:sig_usr: signal 15 received Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips /usr/sbin/opensips[17091]: INFO:core:sig_usr: signal 15 received Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly. Aug 18 09:26:24 Opensips media-dispatcher[976]: DEBUG [main] Connection to OpenSIPS lost: Connection was closed cleanly.

Can you help me about this crash please?

Thank you in advance Best regards Anthony

razvancrainea commented 4 years ago

Please install the opensips-dbg package and send us the bt full with debugging symbols.

Anthony-76 commented 4 years ago

Hi,

Below th result of "bt full" command:

gdb /usr/sbin/opensips core.t.sigp.17102
GNU gdb (Debian 8.2.1-2+b3) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/opensips...Reading symbols from /usr/lib/debug/.build-id/50/dd9fce522e96a71a5755f9c2c9dd33648f8d5c.debug...done.
done.
[New LWP 17102]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/opensips -P /run/opensips/opensips.pid -f /etc/opensips/opensips.cfg'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x000055b8447d8db3 in fm_remove_free (n=0x7f1a28397568, qm=0x7f1a27fd7000) at mem/f_malloc.c:209
209     mem/f_malloc.c: Aucun fichier ou dossier de ce type.
(gdb) bt full
#0  0x000055b8447d8db3 in fm_remove_free (n=0x7f1a28397568, qm=0x7f1a27fd7000) at mem/f_malloc.c:209
        pf = 0x0
        hash = 108
        pf = <optimized out>
        hash = <optimized out>
#1  fm_malloc (qm=0x7f1a27fd7000, size=size@entry=848) at mem/f_malloc.c:438
        frag = 0x7f1a28397568
        n = <optimized out>
        hash = <optimized out>
        __FUNCTION__ = "fm_malloc"
#2  0x00007f1a273b478b in shm_malloc_unsafe (size=848) at ../../mem/shm_mem.h:414
        p = <optimized out>
        p = <optimized out>
#3  update_cloned_msg_from_msg (c_msg=0x7f1a28418a28, msg=msg@entry=0x7f1a300d2098) at sip_msg.c:1190
        copy_mask = 1 '\001'
        l1_len = <optimized out>
        l2_len = <optimized out>
        l3_len = <optimized out>
        p = <optimized out>
        add_rm_aux = 0x7f1a284080f8
        body_lumps_aux = 0x0
        reply_lump_aux = 0x0
        body_bk = 0x0
        __FUNCTION__ = "update_cloned_msg_from_msg"
#4  0x00007f1a2739e080 in w_t_relay (p_msg=0x7f1a300d2098, proxy=<optimized out>, flags=<optimized out>) at tm.c:1349
        p = 0x0
        t = 0x7f1a283733e0
        ret = <optimized out>
        __FUNCTION__ = "w_t_relay"
#5  0x000055b84473d84c in do_action (a=0x7f1a300752b0, msg=0x7f1a300d2098) at action.c:1866
        increment = <optimized out>
        decrement = <optimized out>
        j = <optimized out>
        num_rows = 32764
        cdb_res = <optimized out>
        val_s = {s = 0x1 <error: Cannot access memory at address 0x1>, len = 5060}
        cdb_reply = 0x7ffc42203cc8
        num_cols = <optimized out>
        aux = {s = 0x1 <error: Cannot access memory at address 0x1>, len = 5060}
        i = <optimized out>
        it = <optimized out>
        avp_val = <optimized out>
        avp_name = {n = 0, s = {s = 0x7ffc00000000 <error: Cannot access memory at address 0x7ffc00000000>, len = 482581504}}
        avp_type = 16928
        ret = -5
        v = <optimized out>
        sec = <optimized out>
        usec = <optimized out>
        to = <optimized out>
        p = <optimized out>
        tmp = <optimized out>
        new_uri = <optimized out>
        end = <optimized out>
        crt = <optimized out>
        len = <optimized out>
        i = <optimized out>
        user = 0
        expires = 0
        vals = {{s = 0x7ffc42204240 "\b\253\240D\270U", len = 658522984}, {s = 0x7ffc42204380 "", len = 1149857756}, {s = 0x7f1a300d47b4 "+33xxxxxxxxx@185.x.x.x:5060;transport=udp", len = 12}, {s = 0x0, len = 0}, {
            s = 0x7f1a300d47c1 "185.x.x.x:5060;transport=udp", len = 14}}
        result = {s = 0x7ffc42203cc8 "\f", len = 482581504}
        uri = {user = {s = 0x7f1a300d47d0 "5060;transport=udp", len = 4}, passwd = {s = 0x7f1a300d47d5 "transport=udp", len = 482581504}, host = {s = 0x0, len = 16}, port = {s = 0x10 <error: Cannot access memory at address 0x10>,
--Type <RET> for more, q to quit, c to continue without paging--c
            len = 806166680}, params = {s = 0x0, len = 805783208}, headers = {s = 0x0, len = 1148442700}, port_no = 0, proto = 0, type = ERROR_URI_T, transport = {s = 0x0, len = 0}, ttl = {s = 0x0, len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s = 0x7f1a300d47df "udp", len = 3}, r2 = {s = 0x0, len = 0}, gr = {s = 0x0, len = 0}, transport_val = {s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 0}, lr_val = {s = 0x55b844781c1e <process_lumps+1038> "A\003\\$\020M\213d$\030M\205\344\017\205\207\376\377\377\017\037\200", len = 805173576}, r2_val = {s = 0x11200000206 <error: Cannot access memory at address 0x11200000206>, len = 805173552}, gr_val = {s = 0x7f1a2ffdf948 "p\367\375/\032\177", len = 805173552}, u_name = {{s = 0x7ffc42203f2c "\270U", len = 1109409584}, {s = 0x0, len = 0}, {s = 0x55b844a0a900 <buf> "BYE sip:02xxxxxxxx@185.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP 172.16.254.1:5060;branch=z9hG4bK2950d25a;rport\r\nRoute: <sip:88.x.x.x;lr;ftag=as44d9a0a6;did=db9.298f2662>\r\nMax-Forwa"..., len = 805173576}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806180176}, {s = 0x269 <error: Cannot access memory at address 0x269>, len = 806166680}, {s = 0x7ffc42203f2c "\270U", len = 1109409584}, {s = 0x7f1a283fe860 "BYE sip:+33xxxxxxxxx@185.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP 88.x.x.x:5060;branch=z9hG4bKc885.e2585224.0\r\nVia: SIP/2.0/UDP 172.16.254.1:5060;received=185.26.89.41;branch=z9hG4"..., len = 520}, {s = 0x55b84478a79c <build_req_buf_from_sip_req+3660> "D\003|$\\D\211\375+l$`\211l$\\XZ\351t\371\377\377\017\037D", len = 520}, {s = 0x55b84478a088 <build_req_buf_from_sip_req+1848> "\213E(D\001d$L\001D$PL\215l$PL\215d$LL\211\362H\211\357H\203\354\bH\213\265\370\a", len = 0}, {s = 0x55b8447d9257 <fm_free+327> "H\213D$\bdH3\004%(", len = 1151379712}}, u_val = {{s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 0}, {s = 0x7f1a300d6c48 "\001", len = 0}, {s = 0x55b8447b407c <free_lump+60> "H\307C\b", len = 22}, {s = 0x55b8447d9257 <fm_free+327> "H\213D$\bdH3\004%(", len = 518}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 0}, {s = 0x0, len = 0}, {s = 0x55b8447b5783 <free_lump_list+179> "M\205\355\017\205d\377\377\377H\203\304\b[]A\\A]\303\303\017\037\204", len = 1150473824}, {s = 0x55b844870106 <proto_udp_send+102> "A\211ă\370\377\017\205J\001", len = 806168720}, {s = 0x26900000010 <error: Cannot access memory at address 0x26900000010>, len = 806185256}, {s = 0x0, len = 674706400}}, u_params_no = 65535}
        next_hop = {user = {s = 0x0, len = 482581504}, passwd = {s = 0x7f1a283735d8 "\002", len = 674706872}, host = {s = 0x1 <error: Cannot access memory at address 0x1>, len = 675276896}, port = {s = 0x1 <error: Cannot access memory at address 0x1>, len = 482581504}, params = {s = 0x7f1a2ffdf900 "T", len = 0}, headers = {s = 0x400 <error: Cannot access memory at address 0x400>, len = 674111416}, port_no = 8048, proto = 10246, type = 32538, transport = {s = 0x0, len = 1}, ttl = {s = 0x7f1a273b7eaa <set_1timer+314> "\353\206\017\037@", len = 674706992}, user_param = {s = 0xa <error: Cannot access memory at address 0xa>, len = 1160603628}, maddr = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 0}, method = {s = 0x7f1a283735d8 "\002", len = 1}, lr = {s = 0x13c4 <error: Cannot access memory at address 0x13c4>, len = 806166680}, r2 = {s = 0x7ffc42204140 "\n", len = 674706880}, gr = {s = 0x7f1a273bc8a8 <t_forward_nonack+2888> "H\213\004$\366@y\200\017\204\352\367\377\377H\213t$@L\211\377\350]t\373\377H\213\064$E1\300\061\311L\211", <incomplete sequence \352\277>, len = 674706400}, transport_val = {s = 0x7ffc00000001 <error: Cannot access memory at address 0x7ffc00000001>, len = 1109410112}, ttl_val = {s = 0x7ffc422040e4 "", len = 1109410064}, user_param_val = {s = 0x7ffc00000001 <error: Cannot access memory at address 0x7ffc00000001>, len = 1109410024}, maddr_val = {s = 0x2ffdf90000000000 <error: Cannot access memory at address 0x2ffdf90000000000>, len = 674706896}, method_val = {s = 0x7f1a283735b8 "", len = 1151376616}, lr_val = {s = 0x100000001 <error: Cannot access memory at address 0x100000001>, len = -1}, r2_val = {s = 0x447f0ab1 <error: Cannot access memory at address 0x447f0ab1>, len = 658283076}, gr_val = {s = 0x7f1a00000012 <error: Cannot access memory at address 0x7f1a00000012>, len = 0}, u_name = {{s = 0x0, len = 0}, {s = 0x0, len = 0}, {s = 0x55b800000000 <error: Cannot access memory at address 0x55b800000000>, len = 1}, {s = 0x7f1a300d2098 "\314\064", len = 10}, {s = 0x7f1a00000269 <error: Cannot access memory at address 0x7f1a00000269>, len = 2}, {s = 0x7f1adbdc39b9 <error: Cannot access memory at address 0x7f1adbdc39b9>, len = 1150454960}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = -1}, {s = 0x1 <error: Cannot access memory at address 0x1>, len = 806166680}, {s = 0x0, len = 0}, {s = 0x7f1a283733e0 "", len = 1150455544}}, u_val = {{s = 0x7f1a2737ef33 <t_relay_to+467> "\211Å\300\017\217C\001", len = 0}, {s = 0x0, len = 0}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 0}, {s = 0xffffffff <error: Cannot access memory at address 0xffffffff>, len = 806166680}, {s = 0x7ffc42204270 "\230 \r0\032\177", len = 1150454960}, {s = 0x7f1a30077df0 "\002", len = 1109410408}, {s = 0x7f1a27401d98 <rr_checker+56> "\001Ã\373\376t%H\213\005\362Q", len = 1109410672}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806166680}, {s = 0x7ffc42204370 "\231\251\240D\270U", len = 1109410416}, {s = 0x7f1a2733ee4b <run_rr_callbacks+203> "M\213v\030M\205\366td\363\017oE", len = 1151380232}}, u_params_no = 512}
        u = <optimized out>
        port = 16928
        cmatch = <optimized out>
        aitem = <optimized out>
        adefault = <optimized out>
        spec = <optimized out>
        model = <optimized out>
        val = {rs = {s = 0x7ffc00000000 <error: Cannot access memory at address 0x7ffc00000000>, len = 482581504}, ri = 1, flags = 0}
        pve = <optimized out>
        name_s = {s = 0x7f1a300d47b0 "sip:+33xxxxxxxxx@185.x.x.x:5060;transport=udp", len = 806180432}
        start = {tv_sec = 140721417895136, tv_usec = 0}
        end_time = <optimized out>
        aux_counter = 32764
        __FUNCTION__ = "do_action"
#6  0x000055b844744698 in run_action_list (a=<optimized out>, msg=msg@entry=0x7f1a300d2098) at action.c:172
        ret = -1
        t = 0x7f1a300752b0
#7  0x000055b84477841d in eval_elem (e=0x7f1a30075390, msg=0x7f1a300d2098, val=0x0) at route.c:1373
        ret = -5
        ival = <optimized out>
        lval = {rs = {s = 0x10 <error: Cannot access memory at address 0x10>, len = 16}, ri = 806166680, flags = 32538}
        rval = {rs = {s = 0x0, len = 0}, ri = 1151379851, flags = 21944}
        p = <optimized out>
        i = <optimized out>
        n = <optimized out>
        __FUNCTION__ = "eval_elem"
#8  0x000055b844777d35 in eval_expr (e=0x7f1a30075390, msg=0x7f1a300d2098, val=0x0) at route.c:1697
        rec_lev = 3
        ret = <optimized out>
        __FUNCTION__ = "eval_expr"
#9  0x000055b844777d59 in eval_expr (e=0x7f1a300753e0, msg=msg@entry=0x7f1a300d2098, val=val@entry=0x0) at route.c:1713
        rec_lev = 3
        ret = <optimized out>
        __FUNCTION__ = "eval_expr"
#10 0x000055b844777cfb in eval_expr (e=0x7f1a30075430, msg=msg@entry=0x7f1a300d2098, val=val@entry=0x0) at route.c:1718
        rec_lev = 3
        ret = <optimized out>
        __FUNCTION__ = "eval_expr"
#11 0x000055b84473dc5c in do_action (a=0x7f1a300760d8, msg=0x7f1a300d2098) at action.c:1106
        increment = <optimized out>
        decrement = <optimized out>
        j = <optimized out>
        num_rows = 0
        cdb_res = <optimized out>
        val_s = {s = 0x0, len = 0}
        cdb_reply = 0x0
        num_cols = <optimized out>
        aux = {s = 0x0, len = 0}
        i = <optimized out>
        it = <optimized out>
        avp_val = <optimized out>
        avp_name = {n = 0, s = {s = 0x0, len = 1151379873}}
        avp_type = 0
        ret = -5
        v = <optimized out>
        sec = <optimized out>
        usec = <optimized out>
        to = <optimized out>
        p = <optimized out>
        tmp = <optimized out>
        new_uri = <optimized out>
        end = <optimized out>
        crt = <optimized out>
        len = <optimized out>
        i = <optimized out>
        user = 0
        expires = 0
        vals = {{s = 0x0, len = 0}, {s = 0x0, len = 0}, {s = 0x0, len = 0}, {s = 0x0, len = 0}, {s = 0x0, len = 0}}
        result = {s = 0x0, len = 0}
        uri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 2}, host = {s = 0x55b844fdae00 "0\247\375D\270U", len = 1157475840}, port = {s = 0x0, len = 0}, params = {s = 0x7ffc42204700 "\200k\003E\270U", len = 1}, headers = {s = 0x7ffc422046ff "", len = 822441627}, port_no = 27136, proto = 12549, type = 32538, transport = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 0}, ttl = {s = 0x55b844fdae00 "0\247\375D\270U", len = 0}, user_param = {s = 0x7f1a311922a0 <_IO_file_jumps> "", len = 1109411584}, maddr = {s = 0x1 <error: Cannot access memory at address 0x1>, len = 1109411583}, method = {s = 0x7f1a31049881 <_IO_new_fclose+161> "\211\350[]A\\\303\017\037\204", len = 1}, lr = {s = 0x100002600 <error: Cannot access memory at address 0x100002600>, len = 1151303136}, r2 = {s = 0x7f1a270c758c <exec_avp+1164> "\213D$L\250\177\017\205u\001", len = 0}, gr = {s = 0x0, len = 0}, transport_val = {s = 0x7f1a300d2098 "\314\064", len = 1151303136}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0}, maddr_val = {s = 0x7f1a27f72eea "\211Ã\370\377t߅\300u\225\350V\350\377\377", <incomplete sequence \307>, len = 1157475840}, method_val = {s = 0x1000100000063 <error: Cannot access memory at address 0x1000100000063>, len = 99}, lr_val = {s = 0x7d0 <error: Cannot access memory at address 0x7d0>, len = 1157852032}, r2_val = {s = 0x4000 <error: Cannot access memory at address 0x4000>, len = 1109411680}, gr_val = {s = 0x7f1a27f73297 "H\203\370\377t\333H\203\304\030[A\\A]A^A_]\303\017\037@", len = 806153992}, u_name = {{s = 0x55b845036bf0 "\a", len = 1109411776}, {s = 0x4000 <error: Cannot access memory at address 0x4000>, len = 1157852144}, {s = 0xffffffffffffffff <error: Cannot access memory at address 0xffffffffffffffff>, len = 0}, {s = 0x55b845036b80 "", len = 1109411776}, {s = 0x7f1a27f7f8b5 <mysql_get_parameters+1621> "I\211\305H\215\005\231\320\002", len = 1109412215}, {s = 0x7f1a27f73347 "H\203\370\377t\333H\203\304\030[A\\A]A^A_]\303\017\037@", len = 8174}, {s = 0x55b84503ac20 "", len = 8159}, {s = 0x55b845036c58 "", len = 1157852032}, {s = 0x4 <error: Cannot access memory at address 0x4>, len = 1157868576}, {s = 0x4 <error: Cannot access memory at address 0x4>, len = 1109411824}}, u_val = {{s = 0x7f1a27f7fa8b <mysql_get_parameters+2091> "I\001\\$\020H\211\330[A\\A]A^]\303\017\037@", len = 806153992}, {s = 0x7 <error: Cannot access memory at address 0x7>, len = 1109411952}, {s = 0x55b84503ac20 "", len = 1109411904}, {s = 0x7f1a27f75c0e "H\205\300\177\345ƃ\224", len = 1157868660}, {s = 0x2300cef08 <error: Cannot access memory at address 0x2300cef08>, len = 1157868576}, {s = 0x7f1a27f7964d "\203\373\006u\336I\213\204$\360\004", len = 1109411944}, {s = 0x7 <error: Cannot access memory at address 0x7>, len = 1109412112}, {s = 0x7f1a27f7ea88 "\353\313f\017\037D", len = 1109412016}, {s = 0x7f1a27f76644 "M\213gHH=\377\377\377", len = 806153992}, {s = 0x7f1a30077e70 "DELETE FROM ID_Entrant WHERE id='7fb4fde52282a7b416934b407a08a641@op2.sysun.fr'", len = 79}}, u_params_no = 44071}
        next_hop = {user = {s = 0x0, len = 670523520}, passwd = {s = 0x4f <error: Cannot access memory at address 0x4f>, len = 806153992}, host = {s = 0x7ffc42204a88 "\270T\r0\032\177", len = -1}, port = {s = 0x0, len = 806153992}, params = {s = 0x7ffc42204910 "pI B\374\177", len = 670545885}, headers = {s = 0x7ffc422048d8 "", len = 805797488}, port_no = 3, proto = 0, type = ERROR_URI_T, transport = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = -1}, ttl = {s = 0x7f1a300cef08 "\200k\003E\270U", len = 7}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x7ffc42204938 "!\254\003E\270U", len = 1109412208}, method = {s = 0x7f1a27f7f059 "H\203\304([A\\A]A^A_]\303\017\037\204", len = 79}, lr = {s = 0xffffffff <error: Cannot access memory at address 0xffffffff>, len = 805797488}, r2 = {s = 0x55b84503ac21 "", len = 1109412208}, gr = {s = 0x7f1a300cf688 "Б6'\032\177", len = 1109412488}, transport_val = {s = 0x7f1a3008d480 "\004", len = 805797488}, ttl_val = {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 670784912}, user_param_val = {s = 0x7f1a27fb6474 <db_mysql_submit_query+180> "A\211ƅ\300\017\205\351\b", len = 1109412512}, maddr_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 5060}, method_val = {s = 0x55b8447d9257 <fm_free+327> "H\213D$\bdH3\004%(", len = 1109412488}, lr_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806180024}, r2_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806180024}, gr_val = {s = 0x7f1a300293a0 "\020", len = 806166680}, u_name = {{s = 0x55b844a2e040 <_oser_err_info> "", len = 806166680}, {s = 0x0, len = 0}, {s = 0x55b844744698 <run_action_list+72> "\205\300u\a\203\r\215\216\036", len = 806166680}, {s = 0x7f1a30028280 "\020", len = 0}, {s = 0x2 <error: Cannot access memory at address 0x2>, len = 805475456}, {s = 0x55b84477841d <eval_elem+1309> "\351i\374\377\377f\017\037D", len = 0}, {s = 0x55b844744698 <run_action_list+72> "\205\300u\a\203\r\215\216\036", len = 805187744}, {s = 0x7ffc42204b00 "\230 \r0\032\177", len = 0}, {s = 0x2 <error: Cannot access memory at address 0x2>, len = 805471072}, {s = 0x55b84477841d <eval_elem+1309> "\351i\374\377\377f\017\037D", len = 1}}, u_val = {{s = 0x7f1a300d2098 "\314\064", len = 1151380053}, {s = 0x7f1a300d54b8 "", len = 0}, {s = 0x7f1a300d47c1 "185.x.x.x:5060;transport=udp", len = 40}, {s = 0x7f1a300d2098 "\314\064", len = 806167440}, {s = 0x10001300d2410 <error: Cannot access memory at address 0x10001300d2410>, len = 806167344}, {s = 0x7f1a300d25e0 "", len = 0}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 805806168}, {s = 0x2 <error: Cannot access memory at address 0x2>, len = 805475456}, {s = 0x7f1a300d2098 "\314\064", len = 806166680}, {s = 0x0, len = 0}}, u_params_no = 32053}
        u = <optimized out>
        port = 0
        cmatch = <optimized out>
        aitem = <optimized out>
        adefault = <optimized out>
        spec = <optimized out>
        model = <optimized out>
        val = {rs = {s = 0x0, len = 1151379873}, ri = 10, flags = 0}
        pve = <optimized out>
        name_s = {s = 0x0, len = 0}
        start = {tv_sec = 0, tv_usec = 0}
        end_time = <optimized out>
        aux_counter = 0
        __FUNCTION__ = "do_action"
#12 0x000055b844744698 in run_action_list (a=<optimized out>, msg=0x7f1a300d2098) at action.c:172
        ret = -1
        t = 0x7f1a300760d8
#13 0x000055b84474472c in run_actions (msg=<optimized out>, a=<optimized out>) at action.c:137
        ret = <optimized out>
        ret = <optimized out>
        __FUNCTION__ = "run_actions"
#14 run_actions (a=<optimized out>, msg=<optimized out>) at action.c:118
        ret = <optimized out>
        __FUNCTION__ = "run_actions"
#15 0x000055b84474146c in do_action (a=0x7f1a3002a340, msg=0x7f1a300d2098) at action.c:761
        increment = <optimized out>
        decrement = <optimized out>
        j = <optimized out>
        num_rows = 0
        cdb_res = <optimized out>
        val_s = {s = 0x7ffc422055e0 "", len = 823745600}
        cdb_reply = 0x55b845284760
        num_cols = <optimized out>
        aux = {s = 0x7ffc422055e0 "", len = 823745600}
        i = <optimized out>
        it = <optimized out>
        avp_val = <optimized out>
        avp_name = {n = 1158213160, s = {s = 0x55b84508ee28 "\006", len = 1158218216}}
        avp_type = 0
        ret = -5
        v = <optimized out>
        sec = <optimized out>
        usec = <optimized out>
        to = <optimized out>
        p = <optimized out>
        tmp = <optimized out>
        new_uri = <optimized out>
        end = <optimized out>
        crt = <optimized out>
        len = <optimized out>
        i = <optimized out>
        user = 0
        expires = 0
        vals = {{s = 0x55b845284760 "\320\030-E\270U", len = 8}, {s = 0x55b845284750 "0", len = 806179072}, {s = 0x20 <error: Cannot access memory at address 0x20>, len = 822472015}, {s = 0x0, len = 823745600}, {s = 0x55b844f10438 "\002", len = 1109413376}}
        result = {s = 0x55b845284760 "\320\030-E\270U", len = 36}
        uri = {user = {s = 0x4 <error: Cannot access memory at address 0x4>, len = 482581504}, passwd = {s = 0x7f1a300d5100 "185.x.x.x", len = 10}, host = {s = 0x7ffc42204e60 "\260N B\374\177", len = 1109413744}, port = {s = 0x7f1a300d5100 "185.x.x.x", len = 10}, params = {s = 0xa <error: Cannot access memory at address 0xa>, len = 822809030}, headers = {s = 0xc00000000 <error: Cannot access memory at address 0xc00000000>, len = 1}, port_no = 0, proto = 0, type = ERROR_URI_T, transport = {s = 0x7f1a310b0a6a <set_regs+154> "\205\300u\rI\201\377", len = 9}, ttl = {s = 0x50 <error: Cannot access memory at address 0x50>, len = 16}, user_param = {s = 0x7ffc42204d70 "", len = 8}, maddr = {s = 0x7ffc42204dfc "\032\177", len = 2}, method = {s = 0x7ffc42204e00 "\002", len = 0}, lr = {s = 0x55b80000000b <error: Cannot access memory at address 0x55b80000000b>, len = 1156642464}, r2 = {s = 0x0, len = 806166680}, gr = {s = 0x7f1a27f72eea "\211Ã\370\377t߅\300u\225\350V\350\377\377", <incomplete sequence \307>, len = 2}, transport_val = {s = 0x1000100000063 <error: Cannot access memory at address 0x1000100000063>, len = 99}, ttl_val = {s = 0x7d0 <error: Cannot access memory at address 0x7d0>, len = 1157852032}, user_param_val = {s = 0x7f <error: Cannot access memory at address 0x7f>, len = 8168}, maddr_val = {s = 0x7f1a27f7fa8b <mysql_get_parameters+2091> "I\001\\$\020H\211\330[A\\A]A^]\303\017\037@", len = 806153992}, method_val = {s = 0x5 <error: Cannot access memory at address 0x5>, len = 1109413600}, lr_val = {s = 0x55b84503ac20 "", len = 1109413552}, r2_val = {s = 0x7f1a27f75c0e "H\205\300\177\345ƃ\224", len = 106}, gr_val = {s = 0x244e92ff8 <error: Cannot access memory at address 0x244e92ff8>, len = 8168}, u_name = {{s = 0x0, len = 7}, {s = 0x0, len = 106}, {s = 0x55b844e92ff8 "$fU $tU $ci $rm $T_reply_code", len = 8159}, {s = 0x2010 <error: Cannot access memory at address 0x2010>, len = -80}, {s = 0x7f <error: Cannot access memory at address 0x7f>, len = 511}, {s = 0x7f <error: Cannot access memory at address 0x7f>, len = 8168}, {s = 0x7f1a27f7fa8b <mysql_get_parameters+2091> "I\001\\$\020H\211\330[A\\A]A^]\303\017\037@", len = 806153992}, {s = 0x5 <error: Cannot access memory at address 0x5>, len = 1109413776}, {s = 0x55b84503ac20 "", len = 1109413728}, {s = 0x7f1a27f75c0e "H\205\300\177\345ƃ\224", len = 106}}, u_val = {{s = 0x244e92ff8 <error: Cannot access memory at address 0x244e92ff8>, len = 8159}, {s = 0xc <error: Cannot access memory at address 0xc>, len = 1160619992}, {s = 0x7ffc42204f90 "", len = 0}, {s = 0x7f1a300cef08 "\200k\003E\270U", len = 1109413840}, {s = 0x7f1a27f76644 "M\213gHH=\377\377\377", len = 124}, {s = 0x0, len = 1160601264}, {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 0}, {s = 0x1fd <error: Cannot access memory at address 0x1fd>, len = -80}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1160619992}, {s = 0x1 <error: Cannot access memory at address 0x1>, len = 1150454960}}, u_params_no = 36207}
        next_hop = {user = {s = 0x7f1a300800f0 "\004", len = 805797488}, passwd = {s = 0x7f1a300d54b8 "", len = 482581504}, host = {s = 0x7f1a3119a6f0 <__libc_multiple_threads> "", len = 2}, port = {s = 0x7f1a0000000c <error: Cannot access memory at address 0x7f1a0000000c>, len = 1024}, params = {s = 0x2 <error: Cannot access memory at address 0x2>, len = 1}, headers = {s = 0x7f1a27fdf398 "\001", len = 1148906892}, port_no = 63112, proto = 12300, type = 32538, transport = {s = 0x7f1a300d1808 "", len = 1160620032}, ttl = {s = 0x55b8452d6870 "", len = 128912}, user_param = {s = 0x7f1a31195c40 <main_arena> "", len = 1160619952}, maddr = {s = 0x7f1a3105b79a <_int_free+1770> "\351\276\376\377\377H\215=\320\v\020", len = 2}, method = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1}, lr = {s = 0x55b8452d5ec0 "", len = 1109414096}, r2 = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 805830896}, gr = {s = 0x55b8452d6808 "17102]: CRITICAL:core:sig_usr: segfault in process pid: 17102, id: 13\n", len = 1109414128}, transport_val = {s = 0x0, len = 805830896}, ttl_val = {s = 0x7f1a30077e70 "DELETE FROM ID_Entrant WHERE id='7fb4fde52282a7b416934b407a08a641@op2.sysun.fr'", len = 0}, user_param_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1160603616}, maddr_val = {s = 0x7f1a300266d0 "\020", len = 806166680}, method_val = {s = 0x55b844a2e040 <_oser_err_info> "", len = 806166680}, lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x55b844744698 <run_action_list+72> "\205\300u\a\203\r\215\216\036", len = 806166680}, gr_val = {s = 0x7f1a300182e0 "\020", len = 0}, u_name = {{s = 0x2 <error: Cannot access memory at address 0x2>, len = 805463984}, {s = 0x55b84477841d <eval_elem+1309> "\351i\374\377\377f\017\037D", len = 0}, {s = 0x55b844744698 <run_action_list+72> "\205\300u\a\203\r\215\216\036", len = 805187744}, {s = 0x7ffc42205220 "\230 \r0\032\177", len = 0}, {s = 0x2 <error: Cannot access memory at address 0x2>, len = 805405632}, {s = 0x55b84477841d <eval_elem+1309> "\351i\374\377\377f\017\037D", len = 3}, {s = 0x0, len = 1151379945}, {s = 0x7f1a300d54b8 "", len = 0}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806185832}, {s = 0x7f1a300d2098 "\314\064", len = 52}}, u_val = {{s = 0x7f1a2ffe30a0 "\340/\376/\032\177", len = 805830896}, {s = 0x7f1a30077e70 "DELETE FROM ID_Entrant WHERE id='7fb4fde52282a7b416934b407a08a641@op2.sysun.fr'", len = 0}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 805271768}, {s = 0x2 <error: Cannot access memory at address 0x2>, len = 805463984}, {s = 0x7f1a300d2098 "\314\064", len = 806166680}, {s = 0x0, len = 0}, {s = 0x55b844777d35 <eval_expr+405> "A\211ċ\005\062]\033", len = 806166680}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 2}, {s = 0x7f1a30026a60 "\001", len = 806166680}, {s = 0x7f1a300d2098 "\314\064", len = 0}}, u_params_no = 32241}
        u = <optimized out>
        port = 0
        cmatch = <optimized out>
        aitem = <optimized out>
        adefault = <optimized out>
        spec = <optimized out>
        model = <optimized out>
        val = {rs = {s = 0x55b84508ee28 "\006", len = 1158218216}, ri = 9, flags = 0}
        pve = <optimized out>
        name_s = {s = 0x55b845284750 "0", len = 9}
        start = {tv_sec = 48, tv_usec = 139750468349263}
        end_time = <optimized out>
        aux_counter = 0
        __FUNCTION__ = "do_action"
#16 0x000055b844744698 in run_action_list (a=<optimized out>, msg=msg@entry=0x7f1a300d2098) at action.c:172
        ret = -1
        t = 0x7f1a3002a340
#17 0x000055b844742788 in do_action (a=0x7f1a3002a420, msg=0x7f1a300d2098) at action.c:1124
        increment = <optimized out>
        decrement = <optimized out>
        j = <optimized out>
        num_rows = 21944
        cdb_res = <optimized out>
        val_s = {s = 0xf9 <error: Cannot access memory at address 0xf9>, len = 29}
        cdb_reply = 0x0
        num_cols = <optimized out>
        aux = {s = 0xf9 <error: Cannot access memory at address 0xf9>, len = 29}
        i = <optimized out>
        it = <optimized out>
        avp_val = <optimized out>
        avp_name = {n = 806179112, s = {s = 0x7f1a300d5128 "<sip:02xxxxxxxx@88.x.x.x>", len = 0}}
        avp_type = 17533
        ret = 1
        v = 1
        sec = <optimized out>
        usec = <optimized out>
        to = <optimized out>
        p = <optimized out>
        tmp = <optimized out>
        new_uri = <optimized out>
        end = <optimized out>
        crt = <optimized out>
        len = <optimized out>
        i = <optimized out>
        user = 0
        expires = 0
        vals = {{s = 0x55b844928cb0 <log_level> "", len = 806180560}, {s = 0x7f1a284271b8 "\001", len = 658497107}, {s = 0x7f1a300d5128 "<sip:02xxxxxxxx@88.x.x.x>", len = 1151525000}, {s = 0x2b <error: Cannot access memory at address 0x2b>, len = 1109415176}, {s = 0x0, len = 0}}
        result = {s = 0x0, len = 1149078895}
        uri = {user = {s = 0x5f3ba5ba <error: Cannot access memory at address 0x5f3ba5ba>, len = 1151524864}, passwd = {s = 0x4 <error: Cannot access memory at address 0x4>, len = 806202680}, host = {s = 0x7f1a2834e8a0 "002", len = 1}, port = {s = 0x4 <error: Cannot access memory at address 0x4>, len = 1149078895}, params = {s = 0x7f1a283f0018 "24313993\b", len = 8}, headers = {s = 0x0, len = 482581504}, port_no = 0, proto = 0, type = ERROR_URI_T, transport = {s = 0x400 <error: Cannot access memory at address 0x400>, len = 1151309144}, ttl = {s = 0x5f3ba5ba <error: Cannot access memory at address 0x5f3ba5ba>, len = 674674808}, user_param = {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 670954392}, maddr = {s = 0x7f1a27249f84 <SIP_Dialog_new+116> "H\211\303H\213\005\252", <incomplete sequence \317>, len = 1024}, method = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 6}, lr = {s = 0x1060 <error: Cannot access memory at address 0x1060>, len = 23}, r2 = {s = 0x400 <error: Cannot access memory at address 0x400>, len = 670954392}, gr = {s = 0x1 <error: Cannot access memory at address 0x1>, len = 1151525008}, transport_val = {s = 0x7f1a2724d143 <__dialog_confirmed+1331> "H\213D$\bL\211`\bH\213\005\025\246", len = 1151309144}, ttl_val = {s = 0x7f1a28360f20 "", len = 674631484}, user_param_val = {s = 0x7f1a27257700 <uri> "sip:88.x.x.x:1024", len = 1151525008}, maddr_val = {s = 0x55b8449f9550 <event_shm_threshold> "", len = 674674808}, method_val = {s = 0xf10 <error: Cannot access memory at address 0xf10>, len = 4}, lr_val = {s = 0xa22 <error: Cannot access memory at address 0xa22>, len = 675315368}, r2_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 4}, gr_val = {s = 0x7f1a2839f5f0 "\b", len = 8}, u_name = {{s = 0x7f1a2836b878 "\002", len = 0}, {s = 0x7ffc422055e0 "", len = 658278928}, {s = 0x7f1a270f52e5 <run_dlg_callbacks+213> "H\213[ H\205\333tR\205+t\363H\213\005\217\272\005", len = 4}, {s = 0x7f1a270ec3bc <insert_dlg_timer+124> "I\213u", len = 0}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 0}, {s = 0x7f1a2836b878 "\002", len = 806166680}, {s = 0x3 <error: Cannot access memory at address 0x3>, len = 1150454960}, {s = 0x1 <error: Cannot access memory at address 0x1>, len = 658278928}, {s = 0x7f1a273777a1 <t_should_relay_response+7505> "\351f\347\377\377f.\017\037\204", len = 1}, {s = 0x7ffc42205880 "", len = 1109416060}}, u_val = {{s = 0x0, len = 805173576}, {s = 0x55b844781cbe <process_lumps+1198> "A\003\\$\020M\213d$ M\205\344u\203\017\037", len = 805173576}, {s = 0x324000003cc <error: Cannot access memory at address 0x324000003cc>, len = 805173552}, {s = 0x7f1a2ffdf948 "p\367\375/\032\177", len = 805173552}, {s = 0x3422057d8 <error: Cannot access memory at address 0x3422057d8>, len = 1}, {s = 0x7f1a300d5860 "", len = 0}, {s = 0x55b800000000 <error: Cannot access memory at address 0x55b800000000>, len = 0}, {s = 0x764eab0900000000 <error: Cannot access memory at address 0x764eab0900000000>, len = 1151379712}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806189368}, {s = 0x40 <error: Cannot access memory at address 0x40>, len = 674706400}}, u_params_no = 22336}
        next_hop = {user = {s = 0x7f1a283b7890 "\001", len = 1148722366}, passwd = {s = 0x7f1a2ffdf948 "p\367\375/\032\177", len = 257}, host = {s = 0x7f1a2ffdf930 "\220\367\375/\032\177", len = 1149698310}, port = {s = 0x7f1a2ffdf930 "\220\367\375/\032\177", len = 16}, params = {s = 0x7ffc422057dc "", len = 0}, headers = {s = 0x0, len = 1151379712}, port_no = 63816, proto = 12285, type = 32538, transport = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1109416096}, ttl = {s = 0x7f1a283909c0 <incomplete sequence \310>, len = 1}, user_param = {s = 0x7f1a300d8590 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 172.16.0.200:5060;received=171.33.154.189;branch=z9hG4bK118f4466;rport=5060\r\nFrom: \"006xxxxxxxx\" <sip:04xxxxxxxxxx@op2.sysun.fr>;tag=as50553028\r\nTo: <sip:06xxxxxxxx@op2."..., len = 1}, maddr = {s = 0x7f1a283909e0 "\002", len = 805173504}, method = {s = 0x7f1a2737d359 <send_pr_buffer+185> "\205\300\017\210/\002", len = 674826560}, lr = {s = 0x5 <error: Cannot access memory at address 0x5>, len = 1}, r2 = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806192528}, gr = {s = 0x7f1a000001d6 <error: Cannot access memory at address 0x7f1a000001d6>, len = 0}, transport_val = {s = 0xc8 <error: Cannot access memory at address 0xc8>, len = 200}, ttl_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806192528}, user_param_val = {s = 0x55b8447d9257 <fm_free+327> "H\213D$\bdH3\004%(", len = 0}, maddr_val = {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 200}, method_val = {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 0}, lr_val = {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 806166680}, r2_val = {s = 0x55b844a0aa38 <buf+312> ";tag=KUBypX6KyUc3D\r\nCall-ID: 7fb4fde52282a7b416934b407a08a641@op2.sysun.fr\r\nCSeq: 103 BYE\r\nUser-Agent: Phonegate\r\nX-Asterisk-HangupCause: Normal Clearing\r\nX-Asterisk-HangupCauseCode: 16\r\nContent-Lengt"..., len = 0}, gr_val = {s = 0x55b844a0ab08 <buf+520> "", len = 1151380024}, u_name = {{s = 0x7f1a300d3400 "\001", len = 29}, {s = 0x55b84481d190 <_parse_to+7344> "H\211\305H\205\300\017\204\365/", len = 0}, {s = 0x0, len = 0}, {s = 0x55b844a0aa16 <buf+278> "<sip:02xxxxxxxx@op2.sysun.fr:5060>;tag=KUBypX6KyUc3D\r\nCall-ID: 7fb4fde52282a7b416934b407a08a641@op2.sysun.fr\r\nCSeq: 103 BYE\r\nUser-Agent: Phonegate\r\nX-Asterisk-HangupCause: Normal Clearing\r\nX-Asterisk-"..., len = 29}, {s = 0x7f1a300d3400 "\001", len = 0}, {s = 0x0, len = 806166680}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1151380113}, {s = 0x55b844a0aa8d <buf+397> " BYE\r\nUser-Agent: Phonegate\r\nX-Asterisk-HangupCause: Normal Clearing\r\nX-Asterisk-HangupCauseCode: 16\r\nContent-Length: 0\r\n\r\n", len = 1151380232}, {s = 0x55b8447f60ad <parse_cseq+493> "H\205\300uV\351\367\001", len = 0}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1151380232}}, u_val = {{s = 0x55b844a0ab03 <buf+515> "0\r\n\r\n", len = 1151380232}, {s = 0x7f1a300d2938 "\r", len = 13}, {s = 0x55b8447fa0d5 <get_hdr_field+981> "H\211\303H\205\300\017\204w\a", len = 0}, {s = 0x7f1a273e6be0 <_tm_branch_index> "", len = 1024}, {s = 0x55b8447d8d6f <fm_malloc+1183> "H\215C\030H\213|$\030dH3<%(", len = 0}, {s = 0x300d2098 <error: Cannot access memory at address 0x300d2098>, len = 806166680}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 3}, {s = 0x55b8447d9257 <fm_free+327> "H\213D$\bdH3\004%(", len = 1151380230}, {s = 0x764eab091cc39c00 <error: Cannot access memory at address 0x764eab091cc39c00>, len = 1151380232}, {s = 0xffffffffffffffff <error: Cannot access memory at address 0xffffffffffffffff>, len = 1151380230}}, u_params_no = 45878}
        u = <optimized out>
        port = 17533
        cmatch = <optimized out>
        aitem = <optimized out>
        adefault = <optimized out>
        spec = <optimized out>
        model = <optimized out>
        val = {rs = {s = 0x7f1a300d5128 "<sip:02xxxxxxxx@88.x.x.x>", len = 0}, ri = 31, flags = 0}
        pve = <optimized out>
        name_s = {s = 0x4 <error: Cannot access memory at address 0x4>, len = 482581504}
        start = {tv_sec = 139750451667608, tv_usec = 8524939200284564480}
        end_time = <optimized out>
        aux_counter = 21944
        __FUNCTION__ = "do_action"
#18 0x000055b844744698 in run_action_list (a=a@entry=0x7f1a2ffe9bf8, msg=msg@entry=0x7f1a300d2098) at action.c:172
        ret = -1
        t = 0x7f1a3002a420
#19 0x000055b844744967 in run_actions (msg=0x7f1a300d2098, a=0x7f1a2ffe9bf8) at action.c:137
        ret = <optimized out>
        ret = <optimized out>
        __FUNCTION__ = "run_actions"
#20 run_actions (msg=0x7f1a300d2098, a=0x7f1a2ffe9bf8) at action.c:118
        ret = <optimized out>
        ret = <optimized out>
        __FUNCTION__ = "run_actions"
#21 run_top_route (a=0x7f1a2ffe9bf8, msg=msg@entry=0x7f1a300d2098) at action.c:214
        bk_action_flags = 0
        bk_rec_lev = 0
        ret = <optimized out>
        ctx = 0x0
        __FUNCTION__ = "run_top_route"
#22 0x000055b84474a4e9 in receive_msg (buf=0x55b844a0a900 <buf> "BYE sip:02xxxxxxxx@185.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP 172.16.254.1:5060;branch=z9hG4bK2950d25a;rport\r\nRoute: <sip:88.x.x.x;lr;ftag=as44d9a0a6;did=db9.298f2662>\r\nMax-Forwa"..., len=<optimized out>, rcv_info=rcv_info@entry=0x7ffc42205b50, existing_context=existing_context@entry=0x0, flags=flags@entry=0) at receive.c:209
        ctx = 0x7f1a300d31e0
        msg = 0x7f1a300d2098
        start = {tv_sec = 3123557198882668546, tv_usec = 0}
        rc = 3
        tmp = <optimized out>
        in_buff = {s = 0x55b844a0a900 <buf> "BYE sip:02xxxxxxxx@185.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP 172.16.254.1:5060;branch=z9hG4bK2950d25a;rport\r\nRoute: <sip:88.x.x.x;lr;ftag=as44d9a0a6;did=db9.298f2662>\r\nMax-Forwa"..., len = 520}
        __FUNCTION__ = "receive_msg"
#23 0x000055b8448705e6 in udp_read_req (si=<optimized out>, bytes_read=<optimized out>) at net/proto_udp/proto_udp.c:183
        ri = {src_ip = {af = 2, len = 4, u = {addrl = {140721002191545, 140721417903024}, addr32 = {693705401, 32764, 1109416880, 32764}, addr16 = {6841, 10585, 32764, 0, 23472, 16928, 32764, 0}, addr = "\271\032Y)\374\177\000\000\260[ B\374\177\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {3311458904, 0}, addr32 = {3311458904, 0, 0, 0}, addr16 = {55896, 50528, 0, 0, 0, 0, 0, 0}, addr = "X\332`\305", '\000' <repeats 11 times>}}, src_port = 27064, dst_port = 5060, proto = 1, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "i\270\271\032Y)\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 47209, sin_addr = {s_addr = 693705401}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 47209, sin6_flowinfo = 693705401, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 1150259384}}, bind_address = 0x7f1a2ffdf900}
        len = <optimized out>
        buf = "BYE sip:02xxxxxxxx@185.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP 172.16.254.1:5060;branch=z9hG4bK2950d25a;rport\r\nRoute: <sip:88.x.x.x;lr;ftag=as44d9a0a6;did=db9.298f2662>\r\nMax-Forwa"...
        tmp = <optimized out>
        fromlen = 16
        p = <optimized out>
        msg = {s = 0x55b844a0a900 <buf> "BYE sip:02xxxxxxxx@185.x.x.x:5060;transport=udp SIP/2.0\r\nVia: SIP/2.0/UDP 172.16.254.1:5060;branch=z9hG4bK2950d25a;rport\r\nRoute: <sip:88.x.x.x;lr;ftag=as44d9a0a6;did=db9.298f2662>\r\nMax-Forwa"..., len = 520}
        __FUNCTION__ = "udp_read_req"
#24 0x000055b84485549f in handle_io (idx=<optimized out>, event_type=<optimized out>, fm=<optimized out>) at net/net_udp.c:261
        n = <optimized out>
        read = 17091
        n = <optimized out>
        read = <optimized out>
        __FUNCTION__ = "handle_io"
#25 io_wait_loop_epoll (h=<optimized out>, t=<optimized out>, repeat=<optimized out>) at net/../io_wait_loop.h:284
        ret = <optimized out>
        i = <optimized out>
        e = 0x7f1a300a3448
        ep_event = {events = 2, data = {ptr = 0x310a08ac00000000, fd = 0, u32 = 0, u64 = 3533646392452972544}}
        fd = <optimized out>
        n = 1
        r = 0
        ret = <optimized out>
        n = <optimized out>
        r = <optimized out>
        i = <optimized out>
        e = <optimized out>
        ep_event = <optimized out>
        fd = <optimized out>
        __FUNCTION__ = "io_wait_loop_epoll"
#26 udp_start_processes (chd_rank=chd_rank@entry=0x55b8449f6bc8 <chd_rank>, startup_done=startup_done@entry=0x0) at net/net_udp.c:389
        si = <optimized out>
        pid = <optimized out>
        i = <optimized out>
        p = <optimized out>
        __FUNCTION__ = "udp_start_processes"
#27 0x000055b84472d4c5 in main_loop () at main.c:787
        startup_done = 0x0
        rc = <optimized out>
        chd_rank = 9
        startup_done = <optimized out>
        rc = <optimized out>
        __FUNCTION__ = "main_loop"
#28 main (argc=<optimized out>, argv=<optimized out>) at main.c:1439
        cfg_stream = <optimized out>
        c = <optimized out>
        r = <optimized out>
        tmp = 0x7ffc42206e7c ""
        tmp_len = <optimized out>
        port = <optimized out>
        proto = <optimized out>
        protos_no = <optimized out>
        options = 0x55b8448a0e68 "f:cCm:M:b:l:n:N:rRvdDFEVhw:t:u:g:P:G:W:o:"
        seed = 3151810676
        rfd = <optimized out>
        __FUNCTION__ = "main"
(gdb)

Thank you Anthony

Anthony-76 commented 4 years ago

For more information, this problem is present in 2.4.6 and 2.4.7

Anthony-76 commented 4 years ago

Just in case of, the following result of dump crash (this morning) seems different than yesterday (previous message):

Syslog:

Aug 19 11:12:30 Opensips kernel: [54876.070244] opensips[16248]: segfault at 0 ip 000055cb3437adb3 sp 00007ffff7832970 error 6 in opensips[55cb342cb000+162000] Aug 19 11:12:30 Opensips /usr/sbin/opensips[16248]: CRITICAL:core:sig_usr: segfault in process pid: 16248, id: 14

bt full result:

[New LWP 16234]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/opensips -P /run/opensips/opensips.pid -f /etc/opensips/opensips.cfg'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50      ../sysdeps/unix/sysv/linux/raise.c: Aucun fichier ou dossier de ce type.
(gdb) bt full
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
        set = {__val = {8192, 94331259704256, 0, 6754391495049347328, 11, 1, 1, 21, 11, 94331259704256, 140737345962992, 139992658082325, 0, 94331243603216, 94331260113279, 1597828415}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007f52949ae535 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x55cb354056b0, sa_sigaction = 0x55cb354056b0}, sa_mask = {__val = {94331243611040, 170200, 1, 0, 0, 140737345963376, 18446744073709551615, 0, 4, 94330366722048, 139990164045834, 32,
              140737345964376, 139990164045825, 1, 0}}, sa_flags = -1800128672, sa_restorer = 0xd68}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x000055cb34353643 in sig_alarm_abort (signo=<optimized out>) at main.c:407
        __FUNCTION__ = "sig_alarm_abort"
#3  <signal handler called>
No locals.
#4  0x000055cb3437ba13 in fm_status (qm=0x7f528b989000) at mem/f_malloc.c:734
        f = 0x7f528bd44458
        i = <optimized out>
        j = 1533830785
        h = 107
        unused = 0
        size = 30724895393784
        __FUNCTION__ = "fm_status"
#5  0x000055cb3435455c in shm_status () at mem/shm_mem.h:611
No locals.
#6  cleanup (show_status=show_status@entry=1) at main.c:362
        __FUNCTION__ = "cleanup"
#7  0x000055cb34354c27 in shutdown_opensips (status=status@entry=139) at main.c:495
        proc = <optimized out>
        i = <optimized out>
        n = <optimized out>
        p = <optimized out>
        chld_status = 0
        __FUNCTION__ = "shutdown_opensips"
#8  0x000055cb3435543b in handle_sigs () at main.c:584
        chld = 0
        chld_status = 139
        overall_status = 139
        i = <optimized out>
        do_exit = <optimized out>
        __FUNCTION__ = "handle_sigs"
#9  0x000055cb342cf8a0 in main_loop () at main.c:840
        startup_done = <optimized out>
        rc = <optimized out>
        chd_rank = 31
        startup_done = <optimized out>
        rc = <optimized out>
        __FUNCTION__ = "main_loop"
#10 main (argc=<optimized out>, argv=<optimized out>) at main.c:1439
        cfg_stream = <optimized out>
        c = <optimized out>
        r = <optimized out>
        tmp = 0x7ffff7836e7d ""
        tmp_len = <optimized out>
        port = <optimized out>
        proto = <optimized out>
        protos_no = <optimized out>
        options = 0x55cb34442e68 "f:cCm:M:b:l:n:N:rRvdDFEVhw:t:u:g:P:G:W:o:"
        seed = 3160058239
        rfd = <optimized out>
        __FUNCTION__ = "main"
(gdb)
Anthony-76 commented 4 years ago

Maybe I'm totaly wrong, but the segfault seems appear only on BYE request.

In my "BYE" request, I have this function --> loose_route();

Does this function can make a segfault (memory access). If I remove this function in my BYE request, is it a problem?

I will make more test and give a feedback as soon as possible.

Anthony

Anthony-76 commented 4 years ago

For information, each crash appear on BYE request

On my logs , I Have this:

Aug 27 09:35:32 Opensips /usr/sbin/opensips[26168]: HANGUP 1
Aug 27 09:35:32 Opensips /usr/sbin/opensips[26168]: HANGUP 2
Aug 27 09:35:32 Opensips /usr/sbin/opensips[26168]: HANGUP 3
Aug 27 09:35:32 Opensips /usr/sbin/opensips[26168]: CRITICAL:core:sig_usr: segfault in process pid: 26168, id: 6

Below, the part of my conf file where the crash appear.

Any idea? 

route[raccroche] {
        xlog("L_INFO", "HANGUP 1");
        if (nat_uac_test("2"))
        {
                xlog("L_INFO", "HANGUP 2");
                force_rport();
                fix_contact();
        }
        xlog("L_INFO", "HANGUP 3");
        t_on_branch("2");
        t_on_reply("2");
        t_on_failure("1");

        setflag(1); 
        setflag(3); 
        setflag(2);
        setflag(22);

        if (!t_relay()) {
                xlog("L_INFO", "HANGUP 4");
                setflag(22); 
                setflag(1);
                setflag(2);
                setflag(3);

                t_on_branch("2");
                t_on_reply("2");
                t_on_failure("1");
                send_reply("500","Internal Error");
        };
        xlog("L_INFO", "HANGUP 5");

exit;
}
razvancrainea commented 4 years ago

Hi, Anthony!

Please run OpenSIPS with memory debugging - this will help us gather more information on the crash. You can follow this tutorial to compile OpenSIPS with QM_MALLOC and DBG_MALLOC.

Best regards, Răzvan

Anthony-76 commented 4 years ago

Hi Răzvan,

I compiled Opensips from source with QM_MALLOC and DBG_MALLOC.

I will send you the logs when Opensips will crash.

Thanks again for your help. Best regards Anthony

wdoekes commented 4 years ago

@Anthony-76 : LWP 16234 is the wrong process. That's the parent process. You really want the info from the actual child (LWP 16248) that died.

If you're writing core files, make sure you have %p in the core name (kernel.core_pattern), so any parent core file does not overwrite the child core file.

Anthony-76 commented 4 years ago

Hi Răzvan,

Does this informations are enough for you in order to debug this issue?

At shutdown: https://pastebin.com/xacJuyuM

At run time: https://pastebin.com/WzhaawRD

If you want more informations let me know

Best regards Anthony

Anthony-76 commented 4 years ago

Hi,

I've got a new crash this morning:

Memory logs at crash https://pastebin.com/F6vz2xAn

Core dump: https://pastebin.com/SqiCMDsz

As each crash, it appear on BYE request

If you want any tests/details, let me know

Best regards Anthony

razvancrainea commented 4 years ago

Can you tell us what sort of operations you are doing on BYE messages? I am particularly interested in operations that add/remove certain headers, and the order of the ops.

Anthony-76 commented 4 years ago

Below, tha part of BYE in opensips.cfg

    if (has_totag()) {
            xlog("L_INFO","JE SUIS DANS LA BOUCLE 41\n");
            setflag(22); 
            if (loose_route()) {
                    xlog("L_INFO","JE SUIS DANS LA BOUCLE 42\n");

                    if ($DLG_status==NULL && !match_dialog())
                    {
                            xlog("L_INFO","JE SUIS DANS LA BOUCLE 43\n");

                            exit;
                    }
                    if (!validate_dialog())
                    {
                            xlog("L_INFO","JE SUIS DANS LA BOUCLE 44\n");

                            fix_route_dialog();
                    }
                    setflag(22);

                    if (is_method("BYE") || is_method("CANCEL")) {

                            xlog("L_INFO","JE SUIS DANS LA BOUCLE 45\n");
                            if($fd=="op2.xxx.xxx")
                            {
                                    xlog("L_INFO","JE SUIS DANS LA BOUCLE 46\n");
                                    uac_replace_from("$avp(display)","sip:$fU@88.x.x.x");
                                    uac_replace_to("","sip:$tU@88.x.x.x");
                                    #xlog("REMPLACE TRAME op2.xxx.xxx ");
                            }
                            xlog("L_INFO", "DELETE DANS bdd 4 (id,account) VALUES($ci,$fu)");

                            avp_db_query("DELETE FROM ID_Entrant WHERE id='$ci'","$avp(monip)");

                            loose_route();
                            setflag(22); # ... even if the transaction fails

                            setflag(1);
                            setflag(2);
                            setflag(3);
                            if ( is_method("CANCEL") ) {
                                    exec_avp("php /script/call-control-raccroche.php $fU $tU $ci ","$avp(ou)");
                                    exec_avp("php /script/siptrace.php $fU $tU $ci $rm $T_reply_code");
                                    xlog("L_INFO","JE SUIS DANS LA BOUCLE 47\n");
                                    if ( t_check_trans() )
                                    {
                                            xlog("L_INFO","JE SUIS DANS LA BOUCLE 48\n");
                                            t_relay();
                                    }
                                    xlog("L_INFO", "Call CONTROL le CODE EST ($avp(ou))");
                                    exit;
                            }
                            #t_relay();
                            if (!t_relay()) {
                                    xlog("L_INFO","JE SUIS DANS LA BOUCLE 49\n");
                                    setflag(22); # ... even if the transaction fails

                                    setflag(1);
                                    setflag(2);
                                    setflag(3);

                                    t_on_branch("2");
                                    t_on_reply("2");

                                    send_reply("500","Internal Error");
                            }
                            route(raccroche);

                    }

                    xlog("L_INFO","JE SUIS DANS LA BOUCLE 50\n");
                    record_route();

                    route(raccroche);
                    #exit;

            }

....

route[raccroche] { xlog("L_INFO", "JE RACCROCHE LA COMMUNICATION"); if (nat_uac_test("2")) { xlog("L_INFO", "JE RACCROCHE LA COMMUNICATION 2"); force_rport(); fix_contact(); } xlog("L_INFO", "JE RACCROCHE LA COMMUNICATION 3"); t_on_branch("2"); t_on_reply("2"); t_on_failure("1");

    setflag(1); # do accounting ...
    setflag(3); # ... even if the transaction fails
    setflag(2);
    setflag(22);
    #sip_trace("tid", "dmt", "sip|rest|xlog");

    if (!t_relay()) {
            xlog("L_INFO", "JE RACCROCHE LA COMMUNICATION 4");
            setflag(22); # ... even if the transaction fails

            #sip_trace("tid", "dmt", "sip|rest|xlog");
            setflag(1);
            setflag(2);
            setflag(3);
            ##use_media_proxy();
            t_on_branch("2");
            t_on_failure("1");
            send_reply("500","Internal Error");
    };
    xlog("L_INFO", "JE RACCROCHE LA COMMUNICATION 5");

exit; }

If you want the all opensips.cfg, Let me know how can I send you the all configuration file.?

Best regards Anthony

rrevels-bw commented 4 years ago

Coming late to this one and only have about 30 minutes of running to work with but we upgraded a couple of heavily used proxies to release 2.4.8 last night and had to roll back as they were core dumping every 10 to 20 minutes. There were a variety of process stacks leading up to the crashes from timer threads and response building to one that appeared to happen while processing the initial invite.

The thing they all had in common is where they crashed. This snippet is from a dispatcher options ping being generated but the fm_malloc followed by fm_remove_free was consistently where the crashes occured.

Core was generated by `/usr/local/opensips/sbin/opensips -P /usr/local/opensips/var/run/opensips/opens'. Program terminated with signal 11, Segmentation fault.

0 0x0000000000520c52 in fm_remove_free (n=0x7f0a63d04698, qm=0x7f0a636c8010) at mem/f_malloc.c:209

209 *pf=n->u.nxt_free;

0 0x0000000000520c52 in fm_remove_free (n=0x7f0a63d04698, qm=0x7f0a636c8010) at mem/f_malloc.c:209

    pf = 0x0
    hash = 2

1 fm_malloc (qm=0x7f0a636c8010, size=size@entry=16) at mem/f_malloc.c:438

    frag = 0x7f0a63d04698
    n = <optimized out>
    hash = 2
    __FUNCTION__ = "fm_malloc"

2 0x000000000043dcb7 in hostent_cpy (dst=dst@entry=0x7f0a63d07330, src=0x93e4c0 ) at proxy.c:136

    len = 1
    len2 = <optimized out>
    i = <optimized out>
    r = <optimized out>
    ret = <optimized out>
    __FUNCTION__ = "hostent_cpy"

3 0x000000000043eca2 in mk_proxy (name=name@entry=0x7ffc750933f0, port=, proto=, is_sips=0) at proxy.c:222

    p = 0x7f0a63d07318
    he = <optimized out>
    __FUNCTION__ = "mk_proxy"

4 0x00007f0a22c13156 in uri2proxy (uri=0x7f0a24ff6648, forced_proto=) at ut.h:93

wdoekes commented 4 years ago

we upgraded a couple of heavily used proxies to release 2.4.8

From which version did you upgrade? / To which version did you revert?

As for it crashing in malloc/free: that's likely because the memory got corrupted before then. The memory management heavily relies on pointers. And if they are messed up (point to the wrong thing) you'll get a crash.

What @razvancrainea is after -- correct me if I'm wrong -- is unusual functions being called, or functions being called in an unusual order, as the corruption likely derives from those. So yes, more of your entire cfg helps. (I'm sure you can sanitize it.)

(And if you have a working version, we can check which code has changed between that version and 2.4.8, reducing the search scope.)

Building a non-optimized opensips also helps (I don't know off-hand which Make flags, but you want gcc to end up with -O0). And debug logs leading up to the crash are also nice (but harder to sanitize).

rrevels-bw commented 4 years ago

We upgraded from opensips-2.4.6-12112019.tar.gz (nightly build from December, 11 2019) and reverted back to same.

I'll provide more information if I am able to duplicate this our lab but for some reason that seems to be difficult. It was crashing so often I had to remove core files while investigating just to keep from running out of disk space. In the lab - not a sign of trouble to be seen.

Anyway, the one thing that might be even a little unusual in our call flow is that we are doing rest_client http calls on a lot of calls.

rrevels-bw commented 4 years ago

We've been able to duplicate the crashes in the lab now and are starting to gather information. The first one was odd in that it happened in a thread where i was not expecting to have anything happening.

[root@bw7.lab1 opensips-2.4.8]# opensipsctl ps Process:: ID=0 PID=15136 Type=attendant Process:: ID=2 PID=15139 Type=MI FIFO Process:: ID=3 PID=15140 Type=time_keeper Process:: ID=4 PID=15141 Type=timer Process:: ID=5 PID=15142 Type=SIP receiver udp:192.168.102.99:5060 ... Process:: ID=22 PID=15162 Type=SIP receiver udp:127.0.0.1:5050 Process:: ID=23 PID=15163 Type=SIP receiver udp:127.0.0.1:5050

So the crash happened while processing an internally generated timeout in PID 15163. When internally generated messages need to be created and sent is that task handed off to whatever thread is most idle or something?

I have a core file I'm going to be looking at in a moment but here is what i got from the logs so far.

2020-09-10T19:52:05.993414+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: shm_malloc (322), called from mem/shm_mem.c: sh_realloc(190) 2020-09-10T19:52:05.993418+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: shm_malloc(328), returns address 0x7fdc76c43ac8 frag. 0x7fdc76c43a98 (size=480) on 1 -th hit 2020-09-10T19:52:05.993474+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: CRITICAL:core:sig_usr: segfault in process pid: 15163, id: 23 2020-09-10T19:52:08.659763+00:00 bw7 /usr/local/opensips/sbin/opensips[15174]: CRITICAL:core:handle_worker: dead child 23 (EOF received), pid 15163 2020-09-10T19:52:08.659930+00:00 bw7 /usr/local/opensips/sbin/opensips[15136]: INFO:core:handle_sigs: child process 15163 exited by a signal 11

[root@bw7.lab1 opensips-2.4.8]# grep 0x7fdc76c43ac8 /home/rrevels/opensips.log 2020-09-10T19:50:06.347894+00:00 bw7 /usr/local/opensips/sbin/opensips[15152]: shm_malloc(480), returns address 0x7fdc76c43ac8 frag. 0x7fdc76c43a98 (size=480) on 1 -th hit 2020-09-10T19:52:05.993407+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: shm_free(0x7fdc76c43ac8), called from mem/shm_mem.c: sh_realloc(189) 2020-09-10T19:52:05.993418+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: shm_malloc(328), returns address 0x7fdc76c43ac8 frag. 0x7fdc76c43a98 (size=480) on 1 -th hit 2020-09-10T19:52:15.175510+00:00 bw7 /usr/local/opensips/sbin/opensips[15136]: shm_free(0x7fdc76c43ac8), called from h_table.c: free_cell(140)

rrevels-bw commented 4 years ago

In the log it looks like a thread releases some shared memory and then the above mentioned thread attempts to release that same section of memory. here is where it gets freed and then the first couple lines of the thread that crashes

2020-09-10T19:52:05.974110+00:00 bw7 /usr/local/opensips/sbin/opensips[15153]: pkg_malloc(72), returns address 0x7fdcb5c657c8 frag. 0x7fdcb5c65798 (size=72) on 1 -th hit 2020-09-10T19:52:05.980483+00:00 bw7 /usr/local/opensips/sbin/opensips[15153]: pkg_free(0x7fdcb5c657c8), called from parser/hf.c: free_hdr_field_lst(241) 2020-09-10T19:52:05.992376+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: pkg_malloc (60), called from context.c: context_alloc(119) 2020-09-10T19:52:05.992436+00:00 bw7 /usr/local/opensips/sbin/opensips[15163]: pkg_malloc(64), returns address 0x7fdcb5c65720 frag. 0x7fdcb5c656f0 (size=64) on 1 -th hit

and here is the line that cause the core dump

0 0x000000000050a3eb in free_contacts (_c=0x7fdcb5c657c8) at parser/contact/contact.c:296

(gdb) p _c $1 = (contact_t ) 0x7571655220383034

so, yeah, it wasnt happy with that pointer.

rrevels-bw commented 4 years ago

It occurred to me that the call flow might be of interest on this particular one. A re-invite happened and then a BYE came in before it could get processed end-to-end. So, opensips had to do some clean-up for it.

192.168.102.99 is the opensips proxy

10257 2020-09-10 19:50:04.773434525 192.168.102.9 -> 192.168.102.99 SIP/SDP 963 Request: INVITE sip:+12082447755@192.168.102.99:5060 | 10392 2020-09-10 19:50:05.015317900 192.168.102.99 -> 192.168.102.9 SIP 368 Status: 100 Giving a try | 10508 2020-09-10 19:50:05.185766709 192.168.102.99 -> 192.168.100.107 SIP/SDP 1150 Request: INVITE sip:+12082447755@192.168.100.107:6060 | 10509 2020-09-10 19:50:05.186141337 192.168.100.107 -> 192.168.102.99 SIP 543 Status: 300 Multiple Choices | 10517 2020-09-10 19:50:05.202845787 192.168.102.99 -> 192.168.100.107 SIP 428 Request: ACK sip:+12082447755@192.168.100.107:6060 | 10610 2020-09-10 19:50:05.331082585 192.168.102.99 -> 192.168.126.95 SIP/SDP 1053 Request: INVITE sip:+12082447755@192.168.126.95:5060 | 10611 2020-09-10 19:50:05.332407254 192.168.126.95 -> 192.168.102.99 SIP 394 Status: 100 Trying | 10899 2020-09-10 19:50:05.966654918 192.168.126.95 -> 192.168.102.99 SIP/SDP 859 Status: 200 OK | 10911 2020-09-10 19:50:06.010469494 192.168.102.99 -> 192.168.102.9 SIP/SDP 792 Status: 200 OK | 11071 2020-09-10 19:50:06.344343674 192.168.102.9 -> 192.168.102.99 SIP 425 Request: ACK sip:+12082447755@192.168.126.95:5060 | 11072 2020-09-10 19:50:06.345799080 192.168.102.99 -> 192.168.126.95 SIP 494 Request: ACK sip:+12082447755@192.168.126.95:5060 | 11073 2020-09-10 19:50:06.346477311 192.168.102.9 -> 192.168.102.99 SIP/SDP 884 Request: INVITE sip:+12082447755@192.168.126.95:5060, in-dialog | 11074 2020-09-10 19:50:06.347908673 192.168.102.99 -> 192.168.102.9 SIP 361 Status: 100 Giving a try | 11075 2020-09-10 19:50:06.348118058 192.168.102.99 -> 192.168.126.95 SIP/SDP 954 Request: INVITE sip:+12082447755@192.168.126.95:5060, in-dialog | 11076 2020-09-10 19:50:06.348870030 192.168.126.95 -> 192.168.102.99 SIP 395 Status: 100 Trying | 11221 2020-09-10 19:50:06.524470810 192.168.126.95 -> 192.168.102.99 SIP 423 Request: BYE sip:+12082447745@192.168.102.9:5060 | 11260 2020-09-10 19:50:06.644390989 192.168.102.99 -> 192.168.102.9 SIP 493 Request: BYE sip:+12082447745@192.168.102.9:5060 | 11263 2020-09-10 19:50:06.646887483 192.168.102.9 -> 192.168.102.99 SIP 447 Status: 200 OK | 11265 2020-09-10 19:50:06.659612902 192.168.102.99 -> 192.168.126.95 SIP 379 Status: 200 OK | 22781 2020-09-10 19:52:05.993233777 192.168.102.99 -> 192.168.126.95 SIP 447 Request: CANCEL sip:+12082447755@192.168.126.95:5060 | 22782 2020-09-10 19:52:05.993438433 192.168.102.99 -> 192.168.102.9 SIP 364 Status: 408 Request Timeout | 22784 2020-09-10 19:52:05.993905143 192.168.126.95 -> 192.168.102.99 SIP 353 Status: 481 Call Leg/Transaction Does Not Exist |

wdoekes commented 4 years ago

Good that you're getting somewhere.

I did browse some differences between 1e891b5e312f1f8b133a0f0ce660aba5fd92f6ad (2.4.8) and a5f98158989d0266188ec809e4c1d3429f218771 (2019-12-11), but there are quite a few changes to search through. (And we don't know which modules you're using, so we cannot filter on that.)

You mentioned rest_client. There is a change there with respect to a new enable_expect_100. Have you tried enabling it? (It would revert behaviour to the 2.4.6 version.)

razvancrainea commented 4 years ago

@rrevels-bw thanks for the detailed info, but is there any chance you could post the full backtrace? The contact does indeed seem to be corrupted, and most likely due to the fact that it was parsed by a different process - what I am trying to see is who exactly is parsing the contact and why.

rrevels-bw commented 4 years ago

@razvancrainea sure thing. This one is fairly small so i'll just paste it here. Let me know if you also want the log file with the memory debug stuff in it and ill put it in pastebin or something.

Core was generated by/usr/local/opensips/sbin/opensips -P /usr/local/opensips/var/run/opensips/opens'. Program terminated with signal 11, Segmentation fault.

0 0x000000000050a3eb in free_contacts (_c=0x7fdcb5c657c8) at parser/contact/contact.c:296

296 _c = (_c)->next;

0 0x000000000050a3eb in free_contacts (_c=0x7fdcb5c657c8) at parser/contact/contact.c:296

    ptr = 0x7571655220383034
    __FUNCTION__ = "free_contacts"

1 0x000000000050ad51 in free_contact (_c=0x7fdc76c433e0) at parser/contact/parse_contact.c:107

    __FUNCTION__ = "free_contact"

2 0x00000000004d774b in clean_hdr_field (hf=0x7fdc76c433b0) at parser/hf.c:87

    __FUNCTION__ = "clean_hdr_field"

3 0x00007fdc74a3197e in clean_msg_clone (msg=0x7fdc76c41db8, min=0x7fdc76c41db8, max=0x7fdc76c43560) at sip_msg.h:116

    hdr = 0x7fdc76c433b0
    __FUNCTION__ = "clean_msg_clone"

4 0x00007fdc74a32586 in run_trans_callbacks_locked (type=128, trans=0x7fdc76c40290, req=0x7fdc76c41db8, rpl=0xffffffffffffffff, code=408) at t_hooks.c:265

No locals.

5 0x00007fdc74a018ce in relay_reply (t=0x7fdc76c40290, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_bitmap=0x7ffd11b28e48) at t_reply.c:1356

    relay = 0
    save_clone = 0
    buf = 0x7fdcb5c657c0 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP 192.168.102.9:5060;branch=z9hG4bK00B1d81d9ebdbf4fc5b\r\nFrom: <sip:+12082447745@192.168.102.9>;tag=gK00614ffc\r\nTo: <sip:+12082447747@192.168.102.99>;tag=gK0"...
    res_len = 322
    relayed_code = 408
    relayed_msg = 0xffffffffffffffff
    bm = {to_tag_val = {s = 0x7fdcb5c65885 "gK04f3efa3\r\nCall-ID: 21007035_133134554@192.168.102.9\r\nCSeq: 108947 INVITE\r\nServer: Bandwidth.com CLEC\r\nContent-Length: 0\r\n\r\n", len = 10}}
    totag_retr = 0
    reply_status = RPS_COMPLETED
    uas_rb = 0x7fdc76c40390
    cb_s = {s = 0x7fdcb5c657c0 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP 192.168.102.9:5060;branch=z9hG4bK00B1d81d9ebdbf4fc5b\r\nFrom: <sip:+12082447745@192.168.102.9>;tag=gK00614ffc\r\nTo: <sip:+12082447747@192.168.102.99>;tag=gK0"..., len = 322}
    text = {s = 0x56a1f9 "Request Timeout", len = 15}
    __FUNCTION__ = "relay_reply"

6 0x00007fdc74a3a33e in fake_reply (t=0x7fdc76c40290, branch=0, code=408) at timer.c:257

    cancel_bitmap = 0
    reply_status = 32732

7 0x00007fdc74a3a9f5 in final_response_handler (fr_tl=0x7fdc76c404e0) at timer.c:404

    my_ctx = 0x7fdcb5c65720
    old_ctx = 0x0
    r_buf = 0x7fdc76c40468
    t = 0x7fdc76c40290
    cancel_bitmap = 1
    __FUNCTION__ = "final_response_handler"

8 0x00007fdc74a3caf5 in timer_routine (ticks=383, set=0x0) at timer.c:1088

    tl = 0x7fdc76c404e0
    tmp_tl = 0x7fdc76c45218
    id = 1
    __FUNCTION__ = "timer_routine"

9 0x000000000047ee73 in handle_timer_job () at timer.c:731

    t = 0x7fdc75804c28
    l = 8
    __FUNCTION__ = "handle_timer_job"

10 0x000000000052c69a in handle_io (fm=0x7fdcb57fbca0, idx=3, event_type=1) at net/net_udp.c:265

    n = 0
    read = 5817777
    __FUNCTION__ = "handle_io"

11 0x000000000052b117 in io_wait_loop_epoll (h=0x7f68e0 <_worker_io>, t=1, repeat=0) at net/../io_wait_loop.h:280

    ret = 1
    n = 1
    r = 3
    i = 0
    e = 0x7fdcb57fbca0
    ep_event = {events = 0, data = {ptr = 0x4574bb00000000, fd = 0, u32 = 0, u64 = 19550119900741632}}
    fd = 19
    __FUNCTION__ = "io_wait_loop_epoll"

12 0x000000000052cf47 in udp_start_processes (chd_rank=0x8c247c , startup_done=0x7fdc76107a00) at net/net_udp.c:389

    si = 0x7fdcb54ff330
    pid = 0
    i = 3
    p = 1
    __FUNCTION__ = "udp_start_processes"

13 0x000000000049e2c7 in main_loop () at main.c:787

    chd_rank = 19
    startup_done = 0x7fdc76107a00
    rc = 0
    __FUNCTION__ = "main_loop"

14 0x00000000004a0f15 in main (argc=11, argv=0x7ffd11b29258) at main.c:1439

    cfg_log_stderr = 1
    cfg_stream = 0x272d010
    c = -1
    r = 0
    tmp = 0x7ffd11b2aecc ""
    tmp_len = 0
    port = 77
    proto = 32732
    protos_no = 2
    options = 0x589678 "f:cCm:M:b:l:n:N:rRvdDFEVhw:t:u:g:P:G:W:o:"
    ret = -1
    seed = 3739669194
    rfd = 4
    __FUNCTION__ = "main"

`

rrevels-bw commented 4 years ago

@wdoekes we are not getting 100s in this particular call flow but have had to deal with it in the past so account for it in the config with manually adding Expect header. However, if this is handled in the module now I will try making changes to the parameter and see what happens. Thank You.

rrevels-bw commented 4 years ago

I should also note that one reason we are updating from the version 2.4.6 we are using is that it intermittently (once every 2 to 3 weeks) will core dump on next_branches after a negative response. That one we have never been able to duplicate in the lab so we tried 2.4.7 and had more frequent crashes so jumped at 2.4.8. It's good that we can reproduce this problem in the lab at least.

Here are the modules we load:

loadmodule "signaling.so" loadmodule "proto_udp.so" loadmodule "proto_tcp.so" loadmodule "uri.so" loadmodule "usrloc.so" loadmodule "sl.so" loadmodule "tm.so" loadmodule "rr.so" loadmodule "maxfwd.so" loadmodule "avpops.so" loadmodule "textops.so" loadmodule "permissions.so" loadmodule "dispatcher.so" loadmodule "mi_fifo.so"

loadmodule "mi_datagram.so"

loadmodule "db_mysql.so" loadmodule "db_virtual.so" loadmodule "db_flatstore.so" loadmodule "acc.so" loadmodule "nathelper.so" loadmodule "statistics.so" loadmodule "gflags.so" loadmodule "uac.so" loadmodule "uac_redirect.so" loadmodule "dialog.so" loadmodule "cfgutils.so" loadmodule "benchmark.so" loadmodule "dialplan.so" loadmodule "cachedb_local.so" loadmodule "sipmsgops.so" loadmodule "mathops.so" loadmodule "json.so" loadmodule "rest_client.so" loadmodule "aaa_radius.so" loadmodule "exec.so" loadmodule "httpd.so" loadmodule "mi_json.so"

liviuchircu commented 4 years ago

@rrevels-bw that free_contacts() crash has been solved in df68e3b191a, so make sure to use the latest 2.4.8 commit, possibly by installing via the nightly package repository!

Anthony-76 commented 4 years ago

@razvancrainea

So, I removed these 3 lines in the BYE request, I have no more crash since 1 week. Before I have 1/2 crash by day

Theses lines:

t_on_branch("2"); t_on_reply("2"); t_on_failure("1");

rrevels-bw commented 4 years ago

I've pulled and compiled the latest build. I'll let you know what happens.

stale[bot] commented 4 years ago

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.

stale[bot] commented 4 years ago

Marking as closed due to lack of progress for more than 30 days. If this issue is still relevant, please re-open it with additional details.