ACC Module Crashes Signal 11 When Columns in db_extra Are Missing

[JamuelStarkey]

Running 1.11 HEAD if the opensips script references. During testing I forgot to add additional columns in opensips.cfg that should be written to the acc table (specified in acc module db_extra parameter).

OpenSIPS repeatedly crashes with:

INFO:core:handle_sigs: child process XXXXX exited by a signal 11
INFO:core:handle_sigs: core was generated
INFO:core:handle_sigs: terminating due to SIGCHLD

Only after recompiling with Don't Optimize enabled (CFLAGS = -O0) was I able to get a useful log message in opensips log file:

CRITICAL:db_mysql:wrapper_single_mysql_stmt_prepare: driver error (1054): Unknown column 'acc_db_bug' in 'field list'
ERROR:db_mysql:db_mysql_do_prepared_query: failed to create new context
ERROR:acc:acc_db_request: failed to insert into database

Also of note is that OpenSIPS did NOT crash when compiled with optimization turned off.

[JamuelStarkey]

Here's a sample bt full of a core prior to disabling optimization:

Core was generated by 'opensips -w /tmp'.
Program terminated with signal 11, Segmentation fault.
#0  0x0813ec4e in db_print_columns (_b=0x81f1f71 "method,from_tag,to_tag,callid,sip_code,sip_reason,time,duration,setuptime,created,", _l=65519, _c=0xec0e00, _n=24)
    at db/db_ut.c:274
274                             ret = snprintf(_b + len, _l - len, "%.*s,", _c[i]->len, _c[i]->s);
(gdb) bt all
No symbol "all" in current context.
(gdb) thread apply all
Please specify a command following the thread ID list
(gdb) bt full
#0  0x0813ec4e in db_print_columns (_b=0x81f1f71 "method,from_tag,to_tag,callid,sip_code,sip_reason,time,duration,setuptime,created,", _l=65519, _c=0xec0e00, _n=24)
    at db/db_ut.c:274
        i = 10
        ret = <value optimized out>
        len = 82
        __FUNCTION__ = "db_print_columns"
#1  0x0813ca23 in db_do_insert (_h=0xb7d251f0, _k=0xec0e00, _v=0xec0f80, _n=24, val2str=0x32fc20 <db_mysql_val2str>, submit_query=0x3264b0 <db_mysql_submit_dummy_query>)
    at db/db_query.c:215
        off = <value optimized out>
        ret = 17
        i = <value optimized out>
        no_rows = 0
        buffered_rows = 0x0
        __FUNCTION__ = "db_do_insert"
#2  0x0032d392 in db_mysql_insert (_h=0xb7d251f0, _k=0xec0e00, _v=0xec0f80, _n=24) at dbase.c:1092
        ret = <value optimized out>
#3  0x00e8de4a in acc_db_request (rq=0xb5f606c4, rpl=0xb7d25d48, ins_list=0xec2da0) at acc.c:579
        m = 24
        n = <value optimized out>
        i = <value optimized out>
        my_ps_ins = 0x0
        my_ps = 0x0
        __FUNCTION__ = "acc_db_request"
#4  0x00e988c7 in acc_onreply (t=0xb5f5f6e0, type=128, ps=0xbfd123e0) at acc_logic.c:613
        dlg = 0xb5f5c56c
        flags_s = {s = 0x0, len = -1242171512}
        avp = <value optimized out>
        table = {n = 15331881, s = {s = 0xe9f229 "acc", len = 3}}
        __FUNCTION__ = "acc_onreply"
#5  tmcb_func (t=0xb5f5f6e0, type=128, ps=0xbfd123e0) at acc_logic.c:675
No locals.
#6  0x00bd26cd in run_trans_callbacks (type=128, trans=0xb5f5f6e0, req=0xb5f606c4, rpl=0xb7d25d48, code=200) at t_hooks.c:212
        params = {req = 0xb5f606c4, rpl = 0xb7d25d48, code = 200, param = 0xb5f5c578, extra1 = 0xbfd124dc, extra2 = 0xb5f5f780}
        cbp = 0xb5f5c56c
        backup = 0x81f1a90
        trans_backup = 0xb5f5f6e0
        __FUNCTION__ = "run_trans_callbacks"
#7  0x00bd27f2 in run_trans_callbacks_locked (type=128, trans=0xb5f5f6e0, req=0xb5f606c4, rpl=0xb7d25d48, code=200) at t_hooks.c:265
No locals.
#8  0x00be0aa0 in relay_reply (t=0xb5f5f6e0, p_msg=0xb7d25d48, branch=0, msg_status=200, cancel_bitmap=0xbfd125f0) at t_reply.c:1373
        relay = 0
        save_clone = 0
        buf = 0xb7d28d3c "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.212:5060;received=XXX.XXX.XXX.212;branch=z9hG4bK41fdcfc0;rport=5060\r\nFrom: \"Alice Smith\" <sip:4155551212@XXX.XXX.XXX.212>;tag=as23a843c7\r\nTo: <sip:"...
        res_len = 461
        relayed_code = 200
        relayed_msg = 0xb7d25d48
        bm = {to_tag_val = {s = 0x0, len = 0}}
        totag_retr = 0
        reply_status = RPS_COMPLETED
        uas_rb = 0xb5f5f774
        cb_s = {
          s = 0xb7d28d3c "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.212:5060;received=XXX.XXX.XXX.212;branch=z9hG4bK41fdcfc0;rport=5060\r\nFrom: \"Alice Smith\" <sip:4155551212@XXX.XXX.XXX.212>;tag=as23a843c7\r\nTo: <sip:"..., len = 461}
        text = {s = 0xb7d25d48 "\003", len = -1076812552}
        __FUNCTION__ = "relay_reply"
#9  0x00be1461 in reply_received (p_msg=0xb7d25d48) at t_reply.c:1623
        msg_status = 200
        last_uac_status = <value optimized out>
        branch = 0
        reply_status = <value optimized out>
        timer = <value optimized out>
        cancel_bitmap = 0
        uac = 0xb5f5f7f8
        t = 0xb5f5f6e0
        backup_list = 0x81f1a90
---Type <return> to continue, or q <return> to quit--- 
        __FUNCTION__ = "reply_received"
#10 0x08070529 in forward_reply (msg=0xb7d25d48) at forward.c:575
        new_buf = <value optimized out>
        to = <value optimized out>
        new_len = <value optimized out>
        mod = 0xb7ceea64
        proto = <value optimized out>
        id = <value optimized out>
        send_sock = <value optimized out>
        len = <value optimized out>
        __FUNCTION__ = "forward_reply"
#11 0x080a2e0a in receive_msg (
    buf=0x81e1a80 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.100:5060;branch=z9hG4bK093e.60998cb.0;received=XXX.XXX.XXX.100\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.212:5060;received=XXX.XXX.XXX.212;branch=z9hG4bK41fdcfc0;rport=506"..., len=552, rcv_info=0xbfd12748) at receive.c:214
        start = {tv_sec = 916, tv_usec = -1076811848}
        rc = 3
        tmp = <value optimized out>
        __FUNCTION__ = "receive_msg"
#12 0x080fa670 in udp_rcv_loop () at udp_server.c:424
        len = 552
        tmp = 0x135f58 "\203\354\024\211\306e\241\f"
        fromlen = 16
        ri = {src_ip = {af = 2, len = 4, u = {addrl = {1468924480, 1292096, 5947968, 5751832}, addr32 = {1468924480, 1292096, 5947968, 5751832}, addr16 = {576, 22414, 46912, 
                19, 49728, 90, 50200, 87}, addr = "@\002\216W@\267\023\000@\302Z\000\030\304W"}}, dst_ip = {af = 2, len = 4, u = {addrl = {179664593, 0, 0, 0}, addr32 = {
                179664593, 0, 0, 0}, addr16 = {30417, 2741, 0, 0, 0, 0, 0, 0}, addr = "\321v\265\n", '\000' <repeats 11 times>}}, src_port = 5060, dst_port = 5060, proto = 1, 
          proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023\304@\002\216W\000\000\000\000\000\000\000"}, sin = {sin_family = 2, 
              sin_port = 50195, sin_addr = {s_addr = 1468924480}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, 
              sin6_flowinfo = 1468924480, 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 = 0}}, bind_address = 0xb7d0943c}
        p = 0x1
        msg = {
          s = 0x81e1a80 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.100:5060;branch=z9hG4bK093e.60998cb.0;received=XXX.XXX.XXX.100\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.212:5060;received=XXX.XXX.XXX.212;branch=z9hG4bK41fdcfc0;rport=506"..., len = 552}
        buf = "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.100:5060;branch=z9hG4bK093e.60998cb.0;received=XXX.XXX.XXX.100\r\nVia: SIP/2.0/UDP XXX.XXX.XXX.212:5060;received=XXX.XXX.XXX.212;branch=z9hG4bK41fdcfc0;rport=506"...
        __FUNCTION__ = "udp_rcv_loop"
#13 0x0807637b in main_loop () at main.c:942
        i = 1
        rc = <value optimized out>
        pid = <value optimized out>
        si = 0xb7d0943c
        startup_done = 0x0
        load_p = 0xb5f53560
        chd_rank = 6
        __FUNCTION__ = "main_loop"
#14 0x0807a165 in main (argc=Cannot access memory at address 0x0
) at main.c:1634
        cfg_log_stderr = 0
        cfg_stream = 0x94c3560
        c = <value optimized out>
        r = 0
        tmp = 0x97cf18 "\f"
        tmp_len = <value optimized out>
        port = 1520325
        proto = <value optimized out>
        ret = <value optimized out>
        seed = 636361072
        rfd = 4
        __FUNCTION__ = "main"

[liviuchircu]

Could you please paste the output of "opensips -V"? There was a major acc fix on Friday.

[JamuelStarkey]

On Jul 28, 2014, at 1:35 AM, Liviu Chircu notifications@github.com wrote:

Could you please paste the output of "opensips -V"? There was a major acc fix on Friday.

opensips -V
version: opensips 1.11.2-tls (i386/linux)
flags: STATS: On, USE_IPV6, USE_TCP, USE_TLS, DISABLE_NAGLE, USE_MCAST, SHM_MEM, 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_lt, epoll_et, sigio_rt, select.
git revision: 86c54cc
main.c compiled on 14:19:17 Jul 25 2014 with gcc 4.1.2

[liviuchircu]

This may be a stupid question, but are you sure you haven't done some git pull commands in between your gcc optimization flag changes? In other words, does the backtrace you posted really belong to the latest 1.11 with -O9 enabled?

I'm asking all of this because this exact trace was fixed within commit 86c54cc !

[JamuelStarkey]

On Jul 28, 2014, at 9:37 AM, Liviu Chircu notifications@github.com wrote:

This may be a stupid question, but are you sure you haven't done some git pull commands in between your gcc optimization flag changes? In other words, does the backtrace you posted really belong to the latest 1.11 with -O9 enabled?

I'm asking all of this because this exact trace was fixed within commit 86c54cc !

Actually I did in an attempt to confirm that a patch that we integrate wasn't causing the problem. I was also building RPMS and I might confused myself in the subsequent package deployment. So for sanity's sake I just recompiled git revision: 86c54cc with the optimization flag turned off and I can confirm that I now do see the error in the log and OpenSIPS no longer crashes. Sorry for wasting your time. Feel free to close this ticket.