Use Case Description:

I'm trying to log "user last register status" using function jsonrpc_notification from module jsonrpc-c

invoke in kamailio.cfg:

jsonrpc_notification("last_reg", "{'user': '$au', 'data':['$Ts', '$au', '$ct', '$ua', '$sel(received.proto_ip_port)']}");

according to doc:
jsonrpc_notification is asynchronous delayed job and do not receive response

notifications do not receive a response. Script processing continues in the usual fashion as soon as the notification has been sent.

The rpc server on localhost is implemented with Node.js which never return responses and never close connections ( it only support jsonrpc notification )

Observation and Test:

Crash occurs

I found kamailio crashed periodically about 2-3 days. ( back trace attached at the end)

settings:
1. the amount of total registered users are about 15k ~ 50k; register expiration is 1200 Secs.
2. kamailio start with parameter pkg 1G and shm 5G.
3. I had patched jsonrpc_io.c from #268

json crash log:

Aug 18 22:12:04 SIP-4 kernel: [50538943.565484] kamailio[84670]: segfault at 0 ip 00007f424a3ea3bf sp 00007fff8b3eab60 error 4 in libjson.so.0.1.0[7f424a3e6000+9000]
Aug 18 22:12:23 SIP-4 /home/pkg/kamailio/sbin/kamailio[84620]: ALERT: <core> [main.c:728]: handle_sigs(): child process 84670 exited by a signal 11
Aug 18 22:12:23 SIP-4 /home/pkg/kamailio/sbin/kamailio[84620]: ALERT: <core> [main.c:731]: handle_sigs(): core was generated

sometimes it would not crash, but result in allocation failure. no new connections can be accept.

Aug 20 12:26:04 SIP-5 /home/pkg/kamailio/sbin/kamailio[181104]: ERROR: <core> [tcp_main.c:959]: tcpconn_new(): mem. allocation failure
Aug 20 12:26:04 SIP-5 /home/pkg/kamailio/sbin/kamailio[181104]: ERROR: <core> [tcp_main.c:3977]: handle_new_connect(): tcpconn_new failed, closing socket
Test

use sip-p to start a stress test with RPS 2000 register and observing results both from kamcmd core.shmmem and top command

Kamailio died quickly along with depleting shm memory.
top shows kamailio SHR consumed 4.8G
kamcmd core.shmmem shows free is less than 1MB

the more jsonrpc_notification call we've made, the quicker kamailio out of memory.

MEMDBG

switch on memdbg and shutdown kamailio to get mem status.
see Memory still-in-use summary (shm):
shm_strdup and jsonrpc_notification from jsonrpc_request.c

Aug 24 14:39:41 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status: -----------------------------
Aug 24 14:39:41 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : <core> [main.c:569]: cleanup(): Memory still-in-use summary (shm):
Aug 24 14:39:41 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status: summarizing all alloc'ed. fragments:
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=    96 size=      4608 bytes from dialog: dlg_var.c: new_dlg_var(97)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=    96 size=      2016 bytes from dialog: dlg_var.c: new_dlg_var(106)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=    96 size=      1152 bytes from dialog: dlg_var.c: new_dlg_var(116)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=    40 size=     10568 bytes from tmx: tmx_pretran.c: tmx_check_pretran(264)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=    40 size=      5520 bytes from tmx: tmx_pretran.c: tmx_check_pretran(243)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=   993 size=      7960 bytes from dialog: dlg_handlers.c: dlg_get_iuid_shm_clone(279)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=997818 size= 113547928 bytes from jsonrpc-c: jsonrpc_request.c: shm_strdup(158)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=      1024 bytes from tmx: tmx_pretran.c: tmx_init_pretran_table(90)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     3 size=        64 bytes from usrloc: udomain.c: build_stat_name(51)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from <core>: pt.c: init_pt(110)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from <core>: pt.c: init_pt(105)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=498909 size=  40377480 bytes from jsonrpc-c: jsonrpc_request.c: jsonrpc_notification(135)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from dialog: dlg_hash.c: init_dlg_table(269)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from dialog: dlg_hash.c: init_dlg_table(262)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from dialog: dlg_hash.c: init_dlg_table(257)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     3 size=       216 bytes from <core>: timer.c: register_timer(1011)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from <core>: usr_avp.c: init_avps(90)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from <core>: usr_avp.c: init_avps(89)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status:  count=     1 size=         8 bytes from <core>: mem/shm_mem.c: shm_mem_init_mallocs(179)
Aug 24 14:39:42 SIP-6 /home/pkg/kamailio/sbin/kamailio[263619]: : fm_status: -----------------------------

crash on jsonrpc back trace

#0  0x00007f424a3ea3bf in json_tokener_parse_ex () from /lib/x86_64-linux-gnu/libjson.so.0
No symbol table info available.
#1  0x00007f424a3ebda6 in json_tokener_parse_verbose () from /lib/x86_64-linux-gnu/libjson.so.0
No symbol table info available.
#2  0x00007f424a3ebdfe in json_tokener_parse () from /lib/x86_64-linux-gnu/libjson.so.0
No symbol table info available.
#3  0x00007f424a5f4e1a in cmd_pipe_cb (fd=6, event=2, arg=0x7fff8b3eae60) at jsonrpc_io.c:152
        cmd = 0x7f4304a93cf8
        __FUNCTION__ = "cmd_pipe_cb"
        params = 0x1bc0aa0
        payload = 0x3985b4d6
        req = 0x304a9c5
        json = 0x7fff8b3ead00 "0\f\274\001"
        ns = 0x7f4391ebdc60 "298:{ \"jsonrpc\": \"2.0\", \"method\": \"last_reg\", \"params\": { \"user\": \"597438910\", \"data\": [ \"1439907102\", \"597438910\", \"<sip:597438910@211.246.212.119:55430;transport=tcp>;+sip.instance=\\\"<urn:uuid:f1016"...
        bytes = 140735529528624
        g = 0x7f424a1ac2f8
        sent = 0
#4  0x00007f424a1af254 in event_base_loop () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5
No symbol table info available.
#5  0x00007f424a5f45ef in jsonrpc_io_child_process (cmd_pipe=6, _servers=0x7f4391aba578 "10.1.3.9:5013,3 10.1.3.10:5013,2 10.1.3.11:5013,1")
    at jsonrpc_io.c:92
        __FUNCTION__ = "jsonrpc_io_child_process"
        pipe_ev = {ev_active_next = {tqe_next = 0x0, tqe_prev = 0x1bb9dc0}, ev_next = {tqe_next = 0x7f4391ebda20, tqe_prev = 0x1bc0c00},
          ev_timeout_pos = {ev_next_with_common_timeout = {tqe_next = 0xffffffff, tqe_prev = 0x0}, min_heap_idx = -1}, ev_fd = 6,
          ev_base = 0x1bc0aa0, _ev = {ev_io = {ev_io_next = {tqe_next = 0x0, tqe_prev = 0x1bc0fd0}, ev_timeout = {tv_sec = 0, tv_usec = 0}},
            ev_signal = {ev_signal_next = {tqe_next = 0x0, tqe_prev = 0x1bc0fd0}, ev_ncalls = 0, ev_pncalls = 0x0}}, ev_events = 18,
          ev_res = 2, ev_flags = 130, ev_pri = 0 '\000', ev_closure = 2 '\002', ev_timeout = {tv_sec = 140733193388081, tv_usec = 6631108320},
          ev_callback = 0x7f424a5f4aa7 <cmd_pipe_cb>, ev_arg = 0x7fff8b3eae60}
#6  0x00007f424a5fd50b in child_init (rank=0) at jsonrpc_mod.c:135
        pid = 0
#7  0x0000000000596a41 in init_mod_child (m=0x7f4391ab0db8, rank=0) at sr_module.c:898
        __FUNCTION__ = "init_mod_child"
#8  0x0000000000596779 in init_mod_child (m=0x7f4391ab1110, rank=0) at sr_module.c:895
        __FUNCTION__ = "init_mod_child"
#9  0x0000000000596d55 in init_child (rank=0) at sr_module.c:924
No locals.
#10 0x00000000004aafd3 in main_loop () at main.c:1650
        i = 24
        pid = 84647
        si = 0x0
        si_desc = "udp receiver child=23 sock=38.106.58.4:5063\000n\000\000\000~/q\000\001\000\000\000\260\344\213OB\177\000\000\020\261>\213\377\177\000\000\032\264N\000\000\000\000\000`\261>\213\377\177\000\000\000\224\351\221C\177\000\000 \333\330OB\177\000\000\260\344\213OB\177\000\000$!\314\a\000\000\000\000\260\210A\000\001\000\000"
        nrprocs = 24
        __FUNCTION__ = "main_loop"
#11 0x00000000004b0b5b in main (argc=13, argv=0x7fff8b3eb3d8) at main.c:2533
        cfg_stream = 0x1b1a010
        c = -1
        r = 0
        tmp = 0x7fff8b3ecd59 ""
        tmp_len = 32579
        port = -767281296
        proto = 0
        options = 0x707db8 ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:"
        ret = -1
        seed = 189487301
        rfd = 4
        debug_save = 0
        debug_flag = 0
        dont_fork_cnt = 0
        n_lst = 0x76
        p = 0x7fff8b3eb2de ""
        __FUNCTION__ = "main"
quit



Reply to this email directly or view it on GitHub.