24 Aug
2015
24 Aug
'15
10:11 a.m.
#### 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](http://kamailio.org/docs/modules/4.3.x/modules/jsonrpc-c.html#idp24639…
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:
https://github.com/kamailio/kamailio/issues/296