19 Mar
2015
19 Mar
'15
11:49 p.m.
Hello,
I'm running kamailio:4.2:df86f2a9a09339687af5914b85fe8bd8f8f1f575 and am
getting a periodic crash, once every few days, in response to a CANCEL
message.
The basic back trace is like this:
(gdb) where
#0 0x000000000044fed2 in del_nonshm_lump (lump_list=0x7f48f5681440)
at data_lump.c:677
#1 0x00007f48f5404a15 in free_faked_req (faked_req=0x7f48f5680ea0,
t=0x7f46ee6faeb0) at t_reply.c:975
#2 0x00007f48f5405bdf in run_failure_handlers (t=0x7f46ee6faeb0,
rpl=0xffffffffffffffff, code=487, extra_flags=0) at t_reply.c:1061
#3 0x00007f48f54084e4 in t_should_relay_response (Trans=0x7f46ee6faeb0,
new_code=487, branch=0, should_store=0x7fffce5605e0,
should_relay=0x7fffce5605e4, cancel_data=0x7fffce5606b0,
reply=0xffffffffffffffff) at t_reply.c:1406
#4 0x00007f48f540b045 in relay_reply (t=0x7f46ee6faeb0,
p_msg=0xffffffffffffffff, branch=0, msg_status=487,
cancel_data=0x7fffce5606b0, do_put_on_wait=1) at t_reply.c:1809
#5 0x00007f48f5386832 in cancel_branch (t=0x7f46ee6faeb0, branch=0,
reason=0x0, flags=10) at t_cancel.c:276
#6 0x00007f48f53aff4a in e2e_cancel (cancel_msg=0x7f48f68d69d8,
t_cancel=0x7f46ee8d9c30, t_invite=0x7f46ee6faeb0) at t_fwd.c:1373
#7 0x00007f48f53b4bd0 in t_relay_cancel (p_msg=0x7f48f68d69d8) at
t_fwd.c:1967
#8 0x00007f48f53deaa7 in w_t_relay_cancel (p_msg=0x7f48f68d69d8, _foo=0x0,
_bar=0x0) at tm.c:1743
#9 0x000000000041d364 in do_action (h=0x7fffce560fc0, a=0x7f48f6689f70,
msg=0x7f48f68d69d8) at action.c:1088
#10 0x0000000000429a7a in run_actions (h=0x7fffce560fc0, a=0x7f48f6689f70,
msg=0x7f48f68d69d8) at action.c:1583
#11 0x000000000042a0df in run_actions_safe (h=0x7fffce5622b0,
a=0x7f48f6689f70, msg=0x7f48f68d69d8) at action.c:1648
#12 0x0000000000541158 in rval_get_int (h=0x7fffce5622b0,
msg=0x7f48f68d69d8,
i=0x7fffce561498, rv=0x7f48f668a1e0, cache=0x0) at rvalue.c:924
#13 0x0000000000545390 in rval_expr_eval_int (h=0x7fffce5622b0,
msg=0x7f48f68d69d8, res=0x7fffce561498, rve=0x7f48f668a1d8)
at rvalue.c:1918
#14 0x0000000000545786 in rval_expr_eval_int (h=0x7fffce5622b0,
msg=0x7f48f68d69d8, res=0x7fffce561920, rve=0x7f48f668a948)
at rvalue.c:1926
#15 0x000000000041ce4e in do_action (h=0x7fffce5622b0, a=0x7f48f668c260,
msg=0x7f48f68d69d8) at action.c:1064
#16 0x0000000000429a7a in run_actions (h=0x7fffce5622b0, a=0x7f48f6689808,
msg=0x7f48f68d69d8) at action.c:1583
#17 0x000000000041d2cd in do_action (h=0x7fffce5622b0, a=0x7f48f668c960,
msg=0x7f48f68d69d8) at action.c:1079
#18 0x0000000000429a7a in run_actions (h=0x7fffce5622b0, a=0x7f48f667c628,
msg=0x7f48f68d69d8) at action.c:1583
#19 0x000000000042a1a7 in run_top_route (a=0x7f48f667c628,
msg=0x7f48f68d69d8,
c=0x0) at action.c:1669
#20 0x0000000000507e1a in receive_msg (
buf=0xa6f760 "CANCEL sip:yyy@xxx:5060 SIP/2.0\r\nVia: SIP
/2.0/UDP xxx:5060;branch=z9hG4bK08f.3dc6f0e1.0\r\nFrom: \"yyy\"
<sip:yyy@xxx>;tag=D78eD8FB3SDgc\r\nCall-ID:
e5e48a99-48dd-1233-96b7-782bcb13da6a\r\nTo: <sip:xxx@xxx:5060>\r\nCSeq:
73049624 CANCEL\r\nMax-Forwards: 32\r\nUser-Agent: OpenSIPS (1.9.1-notls
(x86_64/linux))\r\nContent-Length: 0\r\n\r\n", len=394,
rcv_info=0x7fffce5625a0)
at receive.c:216
#21 0x00000000006074ae in udp_rcv_loop () at udp_server.c:521
#22 0x00000000004a5f0b in main_loop () at main.c:1629
#23 0x00000000004ab8bf in main (argc=11, argv=0x7fffce5629c8) at main.c:2578
I'll send a 'thread apply all bt full' privately due to the amount of
private addresses in there, but a quick glance suggests a possible
problem is here:
#5 0x00007f48f5386832 in cancel_branch (t=0x7f46ee6faeb0, branch=0,
reason=0x0, flags=10) at t_cancel.c:276
cancel = 0x1 <Address 0x1 out of bounds>
len = 32584
crb = 0x7f46ee6fb0b0
irb = 0x7f46ee6fb028
ret = 1
tmp_cd = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {
s = 0x0, len = 0}, e2e_cancel = 0x0, packed_hdrs = {s =
0x0,
len = 0}}}}
pcbuf = 0x7f46ee6fb0c0
__FUNCTION__ = "cancel_branch"
#6 0x00007f48f53aff4a in e2e_cancel (cancel_msg=0x7f48f68d69d8,
t_cancel=0x7f46ee8d9c30, t_invite=0x7f46ee6faeb0) at t_fwd.c:1373
cancel_bm = 1
reason = 0x0
free_reason = 0
i = 0
lowest_error = 0
ret = 32584
tmcb = {req = 0x137f66ce710, rpl = 0x7f48f68d69d8, param =
0xf48ab828,
code = -158504488, flags = 32584, branch = 0,
t_rbuf = 0xf80f668f9a0, dst = 0xce5622b0, send_buf = {
s = 0x1ffffffff <Address 0x1ffffffff out of bounds>,
len = -304107664}}
__FUNCTION__ = "e2e_cancel"
#7 0x00007f48f53b4bd0 in t_relay_cancel (p_msg=0x7f48f68d69d8) at
t_fwd.c:1967
t_invite = 0x7f46ee6faeb0
t = 0x7f46ee8d9c30
ret = -323705680
new_tran = 1
Thanks,
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
20 Mar
20 Mar
1:38 a.m.
Hello,
why do you think it is a problem in frame 5?
Send the bt full for at least the first 3 frames.
Cheers,
Daniel
On 19/03/15 19:49, Alex Balashov wrote:
Hello,
I'm running kamailio:4.2:df86f2a9a09339687af5914b85fe8bd8f8f1f575 and
am getting a periodic crash, once every few days, in response to a
CANCEL message.
The basic back trace is like this:
(gdb) where
#0 0x000000000044fed2 in del_nonshm_lump (lump_list=0x7f48f5681440)
at data_lump.c:677
#1 0x00007f48f5404a15 in free_faked_req (faked_req=0x7f48f5680ea0,
t=0x7f46ee6faeb0) at t_reply.c:975
#2 0x00007f48f5405bdf in run_failure_handlers (t=0x7f46ee6faeb0,
rpl=0xffffffffffffffff, code=487, extra_flags=0) at t_reply.c:1061
#3 0x00007f48f54084e4 in t_should_relay_response (Trans=0x7f46ee6faeb0,
new_code=487, branch=0, should_store=0x7fffce5605e0,
should_relay=0x7fffce5605e4, cancel_data=0x7fffce5606b0,
reply=0xffffffffffffffff) at t_reply.c:1406
#4 0x00007f48f540b045 in relay_reply (t=0x7f46ee6faeb0,
p_msg=0xffffffffffffffff, branch=0, msg_status=487,
cancel_data=0x7fffce5606b0, do_put_on_wait=1) at t_reply.c:1809
#5 0x00007f48f5386832 in cancel_branch (t=0x7f46ee6faeb0, branch=0,
reason=0x0, flags=10) at t_cancel.c:276
#6 0x00007f48f53aff4a in e2e_cancel (cancel_msg=0x7f48f68d69d8,
t_cancel=0x7f46ee8d9c30, t_invite=0x7f46ee6faeb0) at t_fwd.c:1373
#7 0x00007f48f53b4bd0 in t_relay_cancel (p_msg=0x7f48f68d69d8) at
t_fwd.c:1967
#8 0x00007f48f53deaa7 in w_t_relay_cancel (p_msg=0x7f48f68d69d8,
_foo=0x0,
_bar=0x0) at tm.c:1743
#9 0x000000000041d364 in do_action (h=0x7fffce560fc0, a=0x7f48f6689f70,
msg=0x7f48f68d69d8) at action.c:1088
#10 0x0000000000429a7a in run_actions (h=0x7fffce560fc0,
a=0x7f48f6689f70,
msg=0x7f48f68d69d8) at action.c:1583
#11 0x000000000042a0df in run_actions_safe (h=0x7fffce5622b0,
a=0x7f48f6689f70, msg=0x7f48f68d69d8) at action.c:1648
#12 0x0000000000541158 in rval_get_int (h=0x7fffce5622b0,
msg=0x7f48f68d69d8,
i=0x7fffce561498, rv=0x7f48f668a1e0, cache=0x0) at rvalue.c:924
#13 0x0000000000545390 in rval_expr_eval_int (h=0x7fffce5622b0,
msg=0x7f48f68d69d8, res=0x7fffce561498, rve=0x7f48f668a1d8)
at rvalue.c:1918
#14 0x0000000000545786 in rval_expr_eval_int (h=0x7fffce5622b0,
msg=0x7f48f68d69d8, res=0x7fffce561920, rve=0x7f48f668a948)
at rvalue.c:1926
#15 0x000000000041ce4e in do_action (h=0x7fffce5622b0, a=0x7f48f668c260,
msg=0x7f48f68d69d8) at action.c:1064
#16 0x0000000000429a7a in run_actions (h=0x7fffce5622b0,
a=0x7f48f6689808,
msg=0x7f48f68d69d8) at action.c:1583
#17 0x000000000041d2cd in do_action (h=0x7fffce5622b0, a=0x7f48f668c960,
msg=0x7f48f68d69d8) at action.c:1079
#18 0x0000000000429a7a in run_actions (h=0x7fffce5622b0,
a=0x7f48f667c628,
msg=0x7f48f68d69d8) at action.c:1583
#19 0x000000000042a1a7 in run_top_route (a=0x7f48f667c628,
msg=0x7f48f68d69d8,
c=0x0) at action.c:1669
#20 0x0000000000507e1a in receive_msg (
buf=0xa6f760 "CANCEL sip:yyy@xxx:5060 SIP/2.0\r\nVia: SIP
/2.0/UDP xxx:5060;branch=z9hG4bK08f.3dc6f0e1.0\r\nFrom: \"yyy\"
<sip:yyy@xxx>;tag=D78eD8FB3SDgc\r\nCall-ID:
e5e48a99-48dd-1233-96b7-782bcb13da6a\r\nTo:
<sip:xxx@xxx:5060>\r\nCSeq: 73049624 CANCEL\r\nMax-Forwards:
32\r\nUser-Agent: OpenSIPS (1.9.1-notls
(x86_64/linux))\r\nContent-Length: 0\r\n\r\n", len=394,
rcv_info=0x7fffce5625a0)
at receive.c:216
#21 0x00000000006074ae in udp_rcv_loop () at udp_server.c:521
#22 0x00000000004a5f0b in main_loop () at main.c:1629
#23 0x00000000004ab8bf in main (argc=11, argv=0x7fffce5629c8) at
main.c:2578
I'll send a 'thread apply all bt full' privately due to the amount of
private addresses in there, but a quick glance suggests a possible
problem is here:
#5 0x00007f48f5386832 in cancel_branch (t=0x7f46ee6faeb0, branch=0,
reason=0x0, flags=10) at t_cancel.c:276
cancel = 0x1 <Address 0x1 out of bounds>
len = 32584
crb = 0x7f46ee6fb0b0
irb = 0x7f46ee6fb028
ret = 1
tmp_cd = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {
s = 0x0, len = 0}, e2e_cancel = 0x0, packed_hdrs = {s
= 0x0,
len = 0}}}}
pcbuf = 0x7f46ee6fb0c0
__FUNCTION__ = "cancel_branch"
#6 0x00007f48f53aff4a in e2e_cancel (cancel_msg=0x7f48f68d69d8,
t_cancel=0x7f46ee8d9c30, t_invite=0x7f46ee6faeb0) at t_fwd.c:1373
cancel_bm = 1
reason = 0x0
free_reason = 0
i = 0
lowest_error = 0
ret = 32584
tmcb = {req = 0x137f66ce710, rpl = 0x7f48f68d69d8, param =
0xf48ab828,
code = -158504488, flags = 32584, branch = 0,
t_rbuf = 0xf80f668f9a0, dst = 0xce5622b0, send_buf = {
s = 0x1ffffffff <Address 0x1ffffffff out of bounds>,
len = -304107664}}
__FUNCTION__ = "e2e_cancel"
#7 0x00007f48f53b4bd0 in t_relay_cancel (p_msg=0x7f48f68d69d8) at
t_fwd.c:1967
t_invite = 0x7f46ee6faeb0
t = 0x7f46ee8d9c30
ret = -323705680
new_tran = 1
Thanks,
-- Alex
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
1:40 a.m.
On 03/19/2015 04:38 PM, Daniel-Constantin Mierla wrote:
Hello,
why do you think it is a problem in frame 5?
Send the bt full for at least the first 3 frames.
The appearance of out-of-bounds access there. But you're right, that is
not necessarily a justifiable conclusion.
I will send bt full privately to you.
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
1:52 a.m.
On 19/03/15 21:40, Alex Balashov wrote:
On 03/19/2015 04:38 PM, Daniel-Constantin Mierla
wrote:
That's a variable declared without initial value and not used according
to the backtrace.
Are you doing any operations in the failure route for a canceled invite?
Like add/remove headers to the invite?
Cheers,
Daniel
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
Hello,
why do you think it is a problem in frame 5?
Send the bt full for at least the first 3 frames.
The appearance of out-of-bounds access there. But you're right, that
is not necessarily a justifiable conclusion.
1:56 a.m.
On 03/19/2015 04:52 PM, Daniel-Constantin Mierla wrote:
Are you doing any operations in the failure route for
a canceled invite?
Like add/remove headers to the invite?
No; only handling for a CANCEL in main route block is:
if(is_method("CANCEL")) {
xlog("L_INFO",
"[R-MAIN:$ci] CANCEL received from $si
(RURI=$ru)\n");
#!ifdef WITH_RTPPROXY
set_rtp_proxy_set("1");
unforce_rtp_proxy();
#!endif
if(!t_relay_cancel()) {
sl_send_reply("500", "Internal Server
Error");
exit;
}
exit;
}
And in failure_route:
if(t_is_canceled()) {
xlog("L_INFO", "[R-OUTBOUND-VENDOR-LNP-DIP-CATCH:$ci] Transaction
cancelled\n");
# Nothing further necessary - CANCEL was already processed
# in TM handling in main request route.
exit;
}
The only other nuance, if it might be relevant, is that the initial
INVITE was processed and relayed out of an rtimer process, after being
t_suspended and being put on an mqueue and t_consumed out of rtimer.
However, this is not the case with CANCEL or any other requests,
sequential or initial.
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
1:58 a.m.
On 03/19/2015 04:56 PM, Alex Balashov wrote:
t_consumed out of rtimer
Sorry, I meant t_continued().
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
1:59 a.m.
The issue seems to be related to the invite transaction (which was
canceled), apparently after running its failure handlers. By chance, do
you know if the invite was relayed?
Daniel
On 19/03/15 21:56, Alex Balashov wrote:
On 03/19/2015 04:52 PM, Daniel-Constantin Mierla
wrote:
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
Are you doing any operations in the failure route
for a canceled invite?
Like add/remove headers to the invite?
No; only handling for a CANCEL in main route block is:
if(is_method("CANCEL")) {
xlog("L_INFO",
"[R-MAIN:$ci] CANCEL received from $si
(RURI=$ru)\n");
#!ifdef WITH_RTPPROXY
set_rtp_proxy_set("1");
unforce_rtp_proxy();
#!endif
if(!t_relay_cancel()) {
sl_send_reply("500", "Internal Server
Error");
exit;
}
exit;
}
And in failure_route:
if(t_is_canceled()) {
xlog("L_INFO", "[R-OUTBOUND-VENDOR-LNP-DIP-CATCH:$ci]
Transaction cancelled\n");
# Nothing further necessary - CANCEL was already processed
# in TM handling in main request route.
exit;
}
The only other nuance, if it might be relevant, is that the initial
INVITE was processed and relayed out of an rtimer process, after being
t_suspended and being put on an mqueue and t_consumed out of rtimer.
However, this is not the case with CANCEL or any other requests,
sequential or initial.
-- Alex
2:04 a.m.
On 03/19/2015 04:59 PM, Daniel-Constantin Mierla wrote:
The issue seems to be related to the invite
transaction (which was
canceled), apparently after running its failure handlers. By chance, do
you know if the invite was relayed?
It does appear to have been:
[R-OUTBOUND-VENDOR-ROUTE-TRY:7842d8b9-4915-1233-75a9-180373eddd8e] ->
Final request URI: sip:xxx@yyy:5060
Mar 19 20:00:44 Proxy1 /usr/local/sbin/kamailio[23976]: INFO:
[R-INVITE-OUTBOUND-HANDLER-POSTROUTE:7842d8b9-4915-1233-75a9-180373eddd8e]
-> Request processing delay: 53 ms
These are the last log lines emitted before my t_relay() call, so I
would safely assume t_relay() was called.
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
2:09 a.m.
I have two core dumps from the last few days with the same crash, and I
took a look at the call flows for both Call-IDs.
Both seem to play out the same way as the crash I sent you:
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21580]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY:e5e48a99-48dd-1233-96b7-782bcb13da6a] ->
Final request URI: sip:yyy@xxx:5060
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21580]: INFO:
[R-INVITE-OUTBOUND-HANDLER-POSTROUTE:e5e48a99-48dd-1233-96b7-782bcb13da6a]
-> Request processing delay: 27 ms
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21580]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY-BRANCH:e5e48a99-48dd-
1233-96b7-782bcb13da6a] Sending media through rtpproxy
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21572]: INFO:
[R-MAIN:e5e48a99-48dd-1233-96b7-782bcb13da6a] CANCEL received from xxx
(RURI=sip:yyy@xxx:5060)
Mar 19 13:22:58 Proxy1 /usr/local/sbin/kamailio[21569]: INFO:
[R-MAIN:e5e48a99-48dd-1233-96b7-782bcb13da6a] CANCEL received from xxx
(RURI=sip:yyy@xxx:5060)
Mar 19 13:23:00 Proxy1 /usr/local/sbin/kamailio[21566]: INFO:
[R-MAIN:e5e48a99-48dd-1233-96b7-782bcb13da6a] CANCEL received from xxx
(RURI=sip:yyy@xxx:5060)
They also have another common characteristic:
The normal call flow is to relay the INVITE on branch .0 to an LNP
gateway, then to capture the LRN from a redirect and relay the INVITE to
its actual destination via branch .1. In all cases, however, there was a
Redis cache hit on the LRN that did not require branch .0.
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
2:13 a.m.
Does it happen that you create the transaction for INVITE with
t_newtran(), then add/remove headers and after that call t_suspend()?
Daniel
On 19/03/15 22:09, Alex Balashov wrote:
I have two core dumps from the last few days with the
same crash, and
I took a look at the call flows for both Call-IDs.
Both seem to play out the same way as the crash I sent you:
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21580]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY:e5e48a99-48dd-1233-96b7-782bcb13da6a] ->
Final request URI: sip:yyy@xxx:5060
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21580]: INFO:
[R-INVITE-OUTBOUND-HANDLER-POSTROUTE:e5e48a99-48dd-1233-96b7-782bcb13da6a]
-> Request processing delay: 27 ms
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21580]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY-BRANCH:e5e48a99-48dd-
1233-96b7-782bcb13da6a] Sending media through rtpproxy
Mar 19 13:22:57 Proxy1 /usr/local/sbin/kamailio[21572]: INFO:
[R-MAIN:e5e48a99-48dd-1233-96b7-782bcb13da6a] CANCEL received from xxx
(RURI=sip:yyy@xxx:5060)
Mar 19 13:22:58 Proxy1 /usr/local/sbin/kamailio[21569]: INFO:
[R-MAIN:e5e48a99-48dd-1233-96b7-782bcb13da6a] CANCEL received from xxx
(RURI=sip:yyy@xxx:5060)
Mar 19 13:23:00 Proxy1 /usr/local/sbin/kamailio[21566]: INFO:
[R-MAIN:e5e48a99-48dd-1233-96b7-782bcb13da6a] CANCEL received from xxx
(RURI=sip:yyy@xxx:5060)
They also have another common characteristic:
The normal call flow is to relay the INVITE on branch .0 to an LNP
gateway, then to capture the LRN from a redirect and relay the INVITE
to its actual destination via branch .1. In all cases, however, there
was a Redis cache hit on the LRN that did not require branch .0.
-- Alex
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
2:16 a.m.
On 03/19/2015 05:13 PM, Daniel-Constantin Mierla wrote:
Does it happen that you create the transaction for
INVITE with
t_newtran(), then add/remove headers and after that call t_suspend()?
Yes, although both the t_newtran() call and any header manipulation
happens after t_continue().
Furthermore, t_newtran() is only called if(!t_lookup_request()).
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
2:17 a.m.
On 03/19/2015 05:16 PM, Alex Balashov wrote:
On 03/19/2015 05:13 PM, Daniel-Constantin Mierla
wrote:
Well, that's not _entirely_ true. It turns out we do remove_hf("Route")
before t_suspend().
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
Does it happen that you create the transaction
for INVITE with
t_newtran(), then add/remove headers and after that call t_suspend()?
Yes, although both the t_newtran() call and any header manipulation
happens after t_continue().
Furthermore, t_newtran() is only called if(!t_lookup_request()).
2:18 a.m.
On 19/03/15 22:16, Alex Balashov wrote:
On 03/19/2015 05:13 PM, Daniel-Constantin Mierla
wrote:
But then is No -- t_continue() should be after
t_suspend().
Daniel
Does it happen that you create the transaction
for INVITE with
t_newtran(), then add/remove headers and after that call t_suspend()?
Yes, although both the t_newtran() call and any header manipulation
happens after t_continue().
Furthermore, t_newtran() is only called if(!t_lookup_request()).
-- Alex
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
2:20 a.m.
On 03/19/2015 05:18 PM, Daniel-Constantin Mierla wrote:
On 19/03/15 22:16, Alex Balashov wrote:
Indeed, it is. If you're asking if anything happens between t_suspend()
and t_continue(), the answer is no. All further processing occurs after
the rtimer thread dequeues and t_continues the transaction.
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
On 03/19/2015 05:13 PM, Daniel-Constantin Mierla
wrote:
But then is No -- t_continue() should be after
t_suspend(). Does it happen that you create the transaction
for INVITE with
t_newtran(), then add/remove headers and after that call t_suspend()?
Yes, although both the t_newtran() call and any header manipulation
happens after t_continue().
2:22 a.m.
On 19/03/15 22:20, Alex Balashov wrote:
On 03/19/2015 05:18 PM, Daniel-Constantin Mierla
wrote:
I asked about what happens before t_suspend() -- if you have there
t_newtran() and then some header/msg changes.
Daniel
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
On 19/03/15 22:16, Alex Balashov wrote:
Indeed, it is. If you're asking if anything happens between
t_suspend() and t_continue(), the answer is no. All further processing
occurs after the rtimer thread dequeues and t_continues the transaction.
On 03/19/2015 05:13 PM, Daniel-Constantin Mierla
wrote:
But then is No -- t_continue() should be after
t_suspend(). Does it happen that you create the transaction
for INVITE with
t_newtran(), then add/remove headers and after that call t_suspend()?
Yes, although both the t_newtran() call and any header manipulation
happens after t_continue().
2:25 a.m.
On 03/19/2015 05:22 PM, Daniel-Constantin Mierla wrote:
I asked about what happens before t_suspend() -- if
you have there
t_newtran() and then some header/msg changes.
Ah, I see. In that case, no, no transaction is created then.
In some other call flows - not these - it is possible for us to create a
transaction in order to support nonce protection on authentication
challenges, i.e.
t_lookup_request();
if(!auth_check("$Ri", "subscriber", "0")) {
...
This happens before t_suspend(), although no header manipulations apart
from removing Route header if present. Is this a bad idea?
However, in this case the source is IP-trusted, so this does not take place.
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
5 p.m.
Can you cherry pick the next commit and give it a try with branch 4.2?
-
https://github.com/kamailio/kamailio/commit/0ee3dc5e3edc49cf62f97ddd87a40b1…
It will be backported if all goes fine.
Cheers,
Daniel
On 19/03/15 22:25, Alex Balashov wrote:
On 03/19/2015 05:22 PM, Daniel-Constantin Mierla
wrote:
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
I asked about what happens before t_suspend() --
if you have there
t_newtran() and then some header/msg changes.
Ah, I see. In that case, no, no transaction is created then.
In some other call flows - not these - it is possible for us to create
a transaction in order to support nonce protection on authentication
challenges, i.e.
t_lookup_request();
if(!auth_check("$Ri", "subscriber", "0")) {
...
This happens before t_suspend(), although no header manipulations
apart from removing Route header if present. Is this a bad idea?
However, in this case the source is IP-trusted, so this does not take
place.
-- Alex
21 Mar
21 Mar
2:05 a.m.
Hello,
On 03/20/2015 08:00 AM, Daniel-Constantin Mierla wrote:
Can you cherry pick the next commit and give it a try
with branch 4.2?
-
https://github.com/kamailio/kamailio/commit/0ee3dc5e3edc49cf62f97ddd87a40b1…
It will be backported if all goes fine.
I've put this into production now, and will let you know if there are
any more crashes. Thank you very much for your hard work in identifying
the problem.
--
Alex Balashov - Principal
Evariste Systems LLC
303 Perimeter Center North
Suite 300
Atlanta, GA 30346
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/
27 Mar
27 Mar
3:17 p.m.
Hello,
The system experienced another crash yesterday, but unfortunately the
core dump is not very insightful, possibly due to being incomplete:
BFD: Warning: /tmp/./core.kamailio.500.1427402410.27498 is truncated:
expected core file size >= 8602058752, found: 1769852928.
[New Thread 27498]
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Failed to read a valid object file image from memory.
Core was generated by `/usr/local/sbin/kamailio -P /var/run/kamailio.pid
-m 8192 -u evaristesys -g eva'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f5286d97e45 in ?? ()
Missing separate debuginfos, use: debuginfo-install
glibc-2.12-1.149.el6_6.5.x86_64
(gdb) where
#0 0x00007f5286d97e45 in ?? ()
Cannot access memory at address 0x7fffbe32a210
That's not much help at all, so I cannot possibly say it is for the same
reasons as before.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
4:47 p.m.
This was a rather peculiar crash:
From the logs, it would appear that Kamailio simply stopped processing
messages at some point. There's about 8 minutes of zero log output at a
time of constantly incoming traffic.
At some point, this situation is resolved when all Kamailio processes
die with a normal SIGTERM, when someone manually restarted it:
Mar 26 20:40:10 Proxy1 /usr/local/sbin/kamailio[27498]: NOTICE: <core>
[main.c:739]: handle_sigs(): Thank you for flying kamailio!!!
Mar 26 20:40:10 Proxy1 /usr/local/sbin/kamailio[27535]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received.
...
But there are a few things here that are difficult to explain from the log:
1. Why was there no SIP stack response for 8 minutes, no logging
activity, etc?
2. We have a script that checks if Kamailio processes are running every
1 second, and restarts Kamailio if it's not. It sends an e-mail
informing us of that development also.
It's a rather naive check:
ps aux | grep kamailio | grep -v 'grep kamailio' | wc -l
But in this case, the script was not triggered, which would imply that
some Kamailio processes--perhaps all--remained running.
There is no indication in the logs that any process died for any reason,
except for the 'signal 15' received by all processes at the time of
manual restart.
3. Why was a core dump generated at the time of the restart, if nothing
crashed?
#3 is most interesting to me, because if it were some other problem,
e.g. blocking of SIP worker threads for some reason, then I wouldn't
expect a core dump upon service shutdown.
There is no other indication of any child process dying with SIGSEGV or
SIGABRT.
-- Alex
On 03/27/2015 06:17 AM, Alex Balashov wrote:
Hello,
The system experienced another crash yesterday, but unfortunately the
core dump is not very insightful, possibly due to being incomplete:
BFD: Warning: /tmp/./core.kamailio.500.1427402410.27498 is truncated:
expected core file size >= 8602058752, found: 1769852928.
[New Thread 27498]
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Failed to read a valid object file image from memory.
Core was generated by `/usr/local/sbin/kamailio -P /var/run/kamailio.pid
-m 8192 -u evaristesys -g eva'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f5286d97e45 in ?? ()
Missing separate debuginfos, use: debuginfo-install
glibc-2.12-1.149.el6_6.5.x86_64
(gdb) where
#0 0x00007f5286d97e45 in ?? ()
Cannot access memory at address 0x7fffbe32a210
That's not much help at all, so I cannot possibly say it is for the same
reasons as before.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
4:49 p.m.
Well, I do have this in 'dmesg':
kamailio[27498]: segfault at 42 ip 00007f5286d97e45 sp 00007fffbe32a210
error 4 in tm.so[7f5286d40000+10d000]
But I don't really know how to look up those offsets easily.
[root@Proxy1 ~]# nm /usr/local/sbin/kamailio | grep 7f5
[root@Proxy1 ~]# nm /usr/local/lib64/kamailio/modules/* | grep 7f5
0000000000007f52 t futex_release
0000000000087f58 r __FUNCTION__.23413
0000000000057f51 r __FUNCTION__.4494
0000000000017f5e T init_rpid_avp
000000000007f5da t w_t_replicate
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
6:58 p.m.
You should be able to find some hints on google about resolving the
instruction pointer address into source code line.
As a lead meanwhile, I guess you using t_replicate() after t_continue(),
right? Once I get some time, I will check to see if there is something
that can have negative impact on such scenario...
Cheers,
Daniel
On 27/03/15 12:49, Alex Balashov wrote:
Well, I do have this in 'dmesg':
kamailio[27498]: segfault at 42 ip 00007f5286d97e45 sp
00007fffbe32a210 error 4 in tm.so[7f5286d40000+10d000]
But I don't really know how to look up those offsets easily.
[root@Proxy1 ~]# nm /usr/local/sbin/kamailio | grep 7f5
[root@Proxy1 ~]# nm /usr/local/lib64/kamailio/modules/* | grep 7f5
0000000000007f52 t futex_release
0000000000087f58 r __FUNCTION__.23413
0000000000057f51 r __FUNCTION__.4494
0000000000017f5e T init_rpid_avp
000000000007f5da t w_t_replicate
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
6:59 p.m.
On 03/27/2015 09:58 AM, Daniel-Constantin Mierla wrote:
As a lead meanwhile, I guess you using t_replicate()
after t_continue(),
right? Once I get some time, I will check to see if there is something
that can have negative impact on such scenario...
No, actually, t_replicate() is not used.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
7:08 p.m.
On 27/03/15 14:59, Alex Balashov wrote:
On 03/27/2015 09:58 AM, Daniel-Constantin Mierla
wrote:
Then the logs were misleading... maybe some corrupted core file ...
Daniel
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
As a lead meanwhile, I guess you using
t_replicate() after t_continue(),
right? Once I get some time, I will check to see if there is something
that can have negative impact on such scenario...
No, actually, t_replicate() is not used.
7:10 p.m.
On 03/27/2015 10:08 AM, Daniel-Constantin Mierla wrote:
Then the logs were misleading... maybe some corrupted
core file ...
It does look that way.
This crash may just have to be created as "idiopathic", since the core
dump contains nothing of interest. Not unless you know how to get
something useful from a core file deemed to be "truncated" ...
BFD: Warning: /tmp/core.kamailio.500.1427402410.27498 is truncated:
expected core file size >= 8602058752, found: 1769852928.
[New Thread 27498]
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Failed to read a valid object file image from memory.
Core was generated by `/usr/local/sbin/kamailio -P /var/run/kamailio.pid
-m 8192 -u evaristesys -g eva'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f5286d97e45 in ?? ()
Missing separate debuginfos, use: debuginfo-install
glibc-2.12-1.149.el6_6.5.x86_64
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
11:11 p.m.
Daniel,
Is there anything in master:0ee3dc5e3edc49cf62f97ddd87a40b12c59b73ff
that might cause this kind of deadlock? I am wondering because I still
have the intuitive sense that all the problems I am experiencing with
Kamailio 4.2 here are caused in some way by my switch to asynchronous
call processing.
I don't have any proof that this deadlock is also an extension of that
general problem domain. I just have that feeling, because the Kamailio
upgrade corresponded to a config upgrade where the major change made was
precisely that.
-- Alex
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
30 Mar
30 Mar
8:07 p.m.
Very unlikely, that commit restored something that used to be in older
version.
On the other hand, I remembered about the report done by Jason that a
CANCEL can end up in some very particular cases in a double lock over
the reply mutex. In your traces sent to me, it was about some cancel
handling, so could be that case. It created a crash because before the
commit 0ee3dc, accessing the branch was rather invalid, then went
through that code and ended up in the lock.
I already pushed a patch for it: 3957db5fb51e23535a89b15c8f05463e5702424d
Maybe you can backport and report the results. It will be part of the
upcoming minor release later this week.
Cheers,
Daniel
On 27/03/15 19:11, Alex Balashov wrote:
Daniel,
Is there anything in master:0ee3dc5e3edc49cf62f97ddd87a40b12c59b73ff
that might cause this kind of deadlock? I am wondering because I still
have the intuitive sense that all the problems I am experiencing with
Kamailio 4.2 here are caused in some way by my switch to asynchronous
call processing.
I don't have any proof that this deadlock is also an extension of that
general problem domain. I just have that feeling, because the Kamailio
upgrade corresponded to a config upgrade where the major change made
was precisely that.
-- Alex
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
10:59 p.m.
Thank you for that, Daniel. I will certainly backport it and keep you
apprised of developments.
On 03/30/2015 11:07 AM, Daniel-Constantin Mierla wrote:
Very unlikely, that commit restored something that
used to be in older
version.
On the other hand, I remembered about the report done by Jason that a
CANCEL can end up in some very particular cases in a double lock over
the reply mutex. In your traces sent to me, it was about some cancel
handling, so could be that case. It created a crash because before the
commit 0ee3dc, accessing the branch was rather invalid, then went
through that code and ended up in the lock.
I already pushed a patch for it: 3957db5fb51e23535a89b15c8f05463e5702424d
Maybe you can backport and report the results. It will be part of the
upcoming minor release later this week.
Cheers,
Daniel
On 27/03/15 19:11, Alex Balashov wrote:
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
Daniel,
Is there anything in master:0ee3dc5e3edc49cf62f97ddd87a40b12c59b73ff
that might cause this kind of deadlock? I am wondering because I still
have the intuitive sense that all the problems I am experiencing with
Kamailio 4.2 here are caused in some way by my switch to asynchronous
call processing.
I don't have any proof that this deadlock is also an extension of that
general problem domain. I just have that feeling, because the Kamailio
upgrade corresponded to a config upgrade where the major change made
was precisely that.
-- Alex
31 Mar
31 Mar
12:40 a.m.
I just encountered another crash with a truncated core dump which was
useless, but I did receive this log output:
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6979]: NOTICE: <core>
[main.c:739]: handle_sigs(): Thank you for flying kamailio!!!
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7009]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7007]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7004]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7006]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7000]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6980]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7008]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6998]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7005]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6984]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6989]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7003]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6988]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7002]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7001]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6999]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6992]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6994]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6981]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6993]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6991]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6990]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6987]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6982]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6995]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6997]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6996]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6985]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6986]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6983]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6979]: : <core>
[mem/f_malloc.c:586]: fm_free(): BUG: fm_free: bad pointer
0x4c36294300000000 (out of memory block!), called from tm: h_table.c:
free_cell(162) - aborting
Any interpretation here? Is this an OOM error? I have given Kamailio 8
GB of SHM; that ought to be enough for anyone, right?
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
1:39 a.m.
The pid 6979 is the main process here (being the one handling the
signals according to the log), not doing anything at runtime, so it
doesn't crash at runtime. The last error is because of the cleanup it
tried to do, which can happen if another process was doing a cleanup of
the structure but didn't finish because it was killed by main process.
The reason for crash should before the message with "Thank you for
flying ..." -- can you check if you get other relevant log messages
before it?
Cheers,
Daniel
On 30/03/15 21:40, Alex Balashov wrote:
I just encountered another crash with a truncated core
dump which was
useless, but I did receive this log output:
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6979]: NOTICE: <core>
[main.c:739]: handle_sigs(): Thank you for flying kamailio!!!
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7009]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7007]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7004]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7006]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7000]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6980]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7008]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6998]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7005]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6984]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6989]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7003]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6988]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7002]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[7001]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6999]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6992]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6994]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6981]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6993]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6991]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6990]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6987]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6982]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6995]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6997]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6996]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6985]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6986]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6983]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received
Mar 30 18:32:04 Proxy1 /usr/local/sbin/kamailio[6979]: : <core>
[mem/f_malloc.c:586]: fm_free(): BUG: fm_free: bad pointer
0x4c36294300000000 (out of memory block!), called from tm: h_table.c:
free_cell(162) - aborting
Any interpretation here? Is this an OOM error? I have given Kamailio 8
GB of SHM; that ought to be enough for anyone, right?
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
1:41 a.m.
On 03/30/2015 04:39 PM, Daniel-Constantin Mierla wrote:
The reason for crash should before the message with
"Thank you for
flying ..." -- can you check if you get other relevant log messages
before it?
I did, but unfortunately there are no relevant messages. Just normal
call processing, and a sudden shutdown. I'll check again to see if a
process might have crashed earlier.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
2:19 a.m.
On 03/30/2015 04:41 PM, Alex Balashov wrote:
I did, but unfortunately there are no relevant
messages. Just normal
call processing, and a sudden shutdown. I'll check again to see if a
process might have crashed earlier.
Unfortunately, there are no other informational messages, such as those
related to the death of a child process earlier on. What I sent is all I
have.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
2:22 a.m.
In the absence of any other information, I am going to chalk this up to
the fact that our SIP stack responsiveness check, which was added to the
monitoring script to monitor for the deadlock I reported earlier, is too
sensitive. It probably restarted Kamailio on a hair trigger, and the
memory error in PID 6979 is just a side effect.
I'm going to disable the SIP check, and hope your patch fixes any
possible deadlock.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
2:54 p.m.
Checking the code, the line corresponds to a SIGTERM or SIGINT handling,
which is normal termination of the application. So it seems that the
application was stopped.
Cheers,
Daniel
On 30/03/15 23:22, Alex Balashov wrote:
In the absence of any other information, I am going to
chalk this up
to the fact that our SIP stack responsiveness check, which was added
to the monitoring script to monitor for the deadlock I reported
earlier, is too sensitive. It probably restarted Kamailio on a hair
trigger, and the memory error in PID 6979 is just a side effect.
I'm going to disable the SIP check, and hope your patch fixes any
possible deadlock.
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
9 Apr
9 Apr
8:10 a.m.
Based on the fact that I have seen no further crashes or deadlocks, I
would be inclined to rule this campaign a success.
On 03/30/2015 11:07 AM, Daniel-Constantin Mierla wrote:
Very unlikely, that commit restored something that
used to be in older
version.
On the other hand, I remembered about the report done by Jason that a
CANCEL can end up in some very particular cases in a double lock over
the reply mutex. In your traces sent to me, it was about some cancel
handling, so could be that case. It created a crash because before the
commit 0ee3dc, accessing the branch was rather invalid, then went
through that code and ended up in the lock.
I already pushed a patch for it: 3957db5fb51e23535a89b15c8f05463e5702424d
Maybe you can backport and report the results. It will be part of the
upcoming minor release later this week.
Cheers,
Daniel
On 27/03/15 19:11, Alex Balashov wrote:
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
Daniel,
Is there anything in master:0ee3dc5e3edc49cf62f97ddd87a40b12c59b73ff
that might cause this kind of deadlock? I am wondering because I still
have the intuitive sense that all the problems I am experiencing with
Kamailio 4.2 here are caused in some way by my switch to asynchronous
call processing.
I don't have any proof that this deadlock is also an extension of that
general problem domain. I just have that feeling, because the Kamailio
upgrade corresponded to a config upgrade where the major change made
was precisely that.
-- Alex
2:53 p.m.
On 09/04/15 05:10, Alex Balashov wrote:
Based on the fact that I have seen no further crashes
or deadlocks, I
would be inclined to rule this campaign a success.
A proof the new embedded systemd
supervising the internal eco-system is
worth it ;-)
Anyhow, thanks for testing and troubleshooting, it is good to know it
was fixed.
Cheers,
Daniel
On 03/30/2015 11:07 AM, Daniel-Constantin Mierla wrote:
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
Very unlikely, that commit restored something
that used to be in older
version.
On the other hand, I remembered about the report done by Jason that a
CANCEL can end up in some very particular cases in a double lock over
the reply mutex. In your traces sent to me, it was about some cancel
handling, so could be that case. It created a crash because before the
commit 0ee3dc, accessing the branch was rather invalid, then went
through that code and ended up in the lock.
I already pushed a patch for it:
3957db5fb51e23535a89b15c8f05463e5702424d
Maybe you can backport and report the results. It will be part of the
upcoming minor release later this week.
Cheers,
Daniel
On 27/03/15 19:11, Alex Balashov wrote:
Daniel,
Is there anything in master:0ee3dc5e3edc49cf62f97ddd87a40b12c59b73ff
that might cause this kind of deadlock? I am wondering because I still
have the intuitive sense that all the problems I am experiencing with
Kamailio 4.2 here are caused in some way by my switch to asynchronous
call processing.
I don't have any proof that this deadlock is also an extension of that
general problem domain. I just have that feeling, because the Kamailio
upgrade corresponded to a config upgrade where the major change made
was precisely that.
-- Alex
9 May
9 May
2:43 a.m.
Unfortunately, we do keep running into total deadlocks with this
approach under high load. We've had to revert async call processing
(with mqueue + rtimer + t_suspend) back to non-async because the
deadlocks were growing politically unacceptable.
I never managed to get a backtrace of the state of the processes at the
time the deadlock occurs, because the customer would soon restart the
proxy when this happened, as it would happen during busy times in the
middle of production days. The only core dumps I have are the crashes on
shutdown, which strikes me as incidental/irrelevant.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
12:56 p.m.
Your message is rather dry in the context of the previous long
discussions, so it is hard to troubleshoot such a report. Can you
provide details what version are you running now? Also, how often it
happens, any error messages before it happens? Do you suspend more than
one time the transaction?
Might not be the case, but if you use locking functions exposed by
htable module, there was a recent fix for them.
Cheers,
Daniel
On 08/05/15 23:43, Alex Balashov wrote:
Unfortunately, we do keep running into total deadlocks
with this
approach under high load. We've had to revert async call processing
(with mqueue + rtimer + t_suspend) back to non-async because the
deadlocks were growing politically unacceptable.
I never managed to get a backtrace of the state of the processes at
the time the deadlock occurs, because the customer would soon restart
the proxy when this happened, as it would happen during busy times in
the middle of production days. The only core dumps I have are the
crashes on shutdown, which strikes me as incidental/irrelevant.
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
10 May
10 May
11:26 p.m.
Hello Daniel,
On 05/09/2015 03:56 AM, Daniel-Constantin Mierla wrote:
Your message is rather dry in the context of the
previous long
discussions, so it is hard to troubleshoot such a report.
Yes, I know. It is not a choice of attitude on my part, but rather a
reflection of the constraints I myself face.
Can you provide details what version are you running
now?
I am running git 4.2:2421e0b987119c083bd5cebe754ae8c97ebfa867.
Also, how often it happens, any error messages before
it happens?
Oddly enough, no; at some point, call processing just stalls. It doesn't
always completely stall, sometimes there is a trickle of call processing
messages, and those look more or less normal. It's just a great
reduction from the previous activity. This state of affairs lasts for a
few minutes, until Kamailio is restarted manually by someone.
Do you suspend more than one time the transaction?
No.
Might not be the case, but if you use locking
functions exposed by
htable module, there was a recent fix for them.
I do not use those.
The general life cycle of an outbound INVITE in this installation is
that AAA is done in the main SIP worker, including digest challenge
authentication, which is used heavily in this installation. I have also
previously encountered crash bugs when using this challenge scenario:
t_lookup_request(); # For nonce replay protection.
if(!auth_check("$Ri", "subscriber", "1")) {
auth_challenge("$Ri", "1");
t_release();
exit;
}
consume_credentials();
... anyway, after this step, the transaction is t_suspended() (once),
the index and label are loaded onto an mqueue, and this is consumed in
one of several rtimer processes which consume the mqueue nearly
continuously (interval 50000u). There, the transaction is t_continued()
and all remaining call processing, including forking for failover, is
performed there.
-- Alex
-- Alex
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
11 May
11 May
12:37 p.m.
On Sunday 10 May 2015, Alex Balashov wrote:
That one doesn't seem to exist in the public repository.
Make sure you have at least 2a0fab2d66b299cb6003cead79a986324d16560d in your
branch. This fixes a timer bug. There might be a lot more bugs like this as
the compiler warnings for this type of errors are squelched, resulting in the
hiding of tons of warnings.
--
Greetings,
Alex Hermann
Can you
provide details what version are you running now?
I am running git 4.2:2421e0b987119c083bd5cebe754ae8c97ebfa867.
1:03 p.m.
Hello,
On 11/05/15 09:37, Alex Hermann wrote:
On Sunday 10 May 2015, Alex Balashov wrote:
That one doesn't seem to exist in
the public repository.
Make sure you have at least 2a0fab2d66b299cb6003cead79a986324d16560d in your
branch. This fixes a timer bug. There might be a lot more bugs like this as
the compiler warnings for this type of errors are squelched, resulting in the
hiding of tons of warnings.
I pushed a patch over the weekend that is related to the report of a
crash when removing from timer a suspended transaction:
-
https://github.com/kamailio/kamailio/commit/96b84ba4d7f5ee4a763fe7db81bbf4f…
I haven't had the time for deep analyze, but there were two different
mutexes (async and reply loacks) used for handling the suspended
transaction, and that may cause problems in some corner cases. The patch
changes to use of reply lock which is re-entrant, so the process that
acquired the transaction can handle it properly, no matter it does
continue or reply/failure route handling.
It will be backported as soon as more testing is performed.
Cheers,
Daniel
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
Can you
provide details what version are you running now?
I am running git
4.2:2421e0b987119c083bd5cebe754ae8c97ebfa867.
27 Mar
27 Mar
7 p.m.
It would be good to add some sip keepalive monitoring (e.g., cron job
with sipsak sending options) that will alert/restart in case of no
response. The monit tool can also send sip keepalives and take actions
on no response.
On a deadlock, checking process table is not enough. There should have
been high cpu usage, though, if you monitored that.
Cheers,
Daniel
On 27/03/15 12:47, Alex Balashov wrote:
This was a rather peculiar crash:
From the logs, it would appear that Kamailio simply stopped processing
messages at some point. There's about 8 minutes of zero log output at
a time of constantly incoming traffic.
At some point, this situation is resolved when all Kamailio processes
die with a normal SIGTERM, when someone manually restarted it:
Mar 26 20:40:10 Proxy1 /usr/local/sbin/kamailio[27498]: NOTICE: <core>
[main.c:739]: handle_sigs(): Thank you for flying kamailio!!!
Mar 26 20:40:10 Proxy1 /usr/local/sbin/kamailio[27535]: INFO: <core>
[main.c:850]: sig_usr(): signal 15 received.
...
But there are a few things here that are difficult to explain from the
log:
1. Why was there no SIP stack response for 8 minutes, no logging
activity, etc?
2. We have a script that checks if Kamailio processes are running
every 1 second, and restarts Kamailio if it's not. It sends an e-mail
informing us of that development also.
It's a rather naive check:
ps aux | grep kamailio | grep -v 'grep kamailio' | wc -l
But in this case, the script was not triggered, which would imply that
some Kamailio processes--perhaps all--remained running.
There is no indication in the logs that any process died for any
reason, except for the 'signal 15' received by all processes at the
time of manual restart.
3. Why was a core dump generated at the time of the restart, if
nothing crashed?
#3 is most interesting to me, because if it were some other problem,
e.g. blocking of SIP worker threads for some reason, then I wouldn't
expect a core dump upon service shutdown.
There is no other indication of any child process dying with SIGSEGV
or SIGABRT.
-- Alex
On 03/27/2015 06:17 AM, Alex Balashov wrote:
--
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com
Hello,
The system experienced another crash yesterday, but unfortunately the
core dump is not very insightful, possibly due to being incomplete:
BFD: Warning: /tmp/./core.kamailio.500.1427402410.27498 is truncated:
expected core file size >= 8602058752, found: 1769852928.
[New Thread 27498]
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Cannot access memory at address 0x7f52891e3168
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Failed to read a valid object file image from memory.
Core was generated by `/usr/local/sbin/kamailio -P /var/run/kamailio.pid
-m 8192 -u evaristesys -g eva'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f5286d97e45 in ?? ()
Missing separate debuginfos, use: debuginfo-install
glibc-2.12-1.149.el6_6.5.x86_64
(gdb) where
#0 0x00007f5286d97e45 in ?? ()
Cannot access memory at address 0x7fffbe32a210
That's not much help at all, so I cannot possibly say it is for the same
reasons as before.
7:06 p.m.
On 03/27/2015 10:00 AM, Daniel-Constantin Mierla wrote:
It would be good to add some sip keepalive monitoring
(e.g., cron job
with sipsak sending options) that will alert/restart in case of no
response. The monit tool can also send sip keepalives and take actions
on no response.
On a deadlock, checking process table is not enough. There should have
been high cpu usage, though, if you monitored that.
I agree that this type of monitoring is insufficient. It was a
short-term stop-gap measure to restart Kamailio if it crashes (due to
the original crash bug that is the subject of this thread).
Normally, Kamailio is so stable we don't really worry about it crashing,
so there wasn't much of a need for monitoring it or its SIP
responsiveness. :-) It runs for months or years without issue.
--
Alex Balashov | Principal | Evariste Systems LLC
303 Perimeter Center North, Suite 300
Atlanta, GA 30346
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
3283
days inactive
3336
days old
42 comments
3 participants
participants (3)
-
Alex Balashov -
Alex Hermann -
Daniel-Constantin Mierla