Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING: <script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed
Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size.
Any ideas what it could be, or how to investegate further?
I think my next steps would be to increase the private memory og to increase children=4 to children=8
Hello,
do you get high CPU usage by kamailio?
What you can do is to attach with gdb to kamailio processes and see what they are doing:
gdb /path/to/kamailio pid_of_a_kamailio_process bt
You should attach to the sip worker processes - you can find the type of processes with 'kamctl ps'.
Cheers, Daniel
On 4/7/11 9:02 PM, Morten Isaksen wrote:
Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING:
<script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size. Any ideas what it could be, or how to investegate further? I think my next steps would be to increase the private memory og to increase children=4 to children=8
Hi,
No, normal CPU usage.
Thanks for the sugestion - I will try that next time.
/Morten
On Thu, Apr 7, 2011 at 10:52 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:
Hello,
do you get high CPU usage by kamailio?
What you can do is to attach with gdb to kamailio processes and see what they are doing:
gdb /path/to/kamailio pid_of_a_kamailio_process bt
You should attach to the sip worker processes - you can find the type of processes with 'kamctl ps'.
Cheers, Daniel
On 4/7/11 9:02 PM, Morten Isaksen wrote:
Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING:
<script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size. Any ideas what it could be, or how to investegate further? I think my next steps would be to increase the private memory og to increase children=4 to children=8
-- Daniel-Constantin Mierla http://www.asipto.com
Hi,
It happend again.
I got the result from gdb. Here is the output from a bt indside gdb for each worker and one bt full for one of the workers.
They are all stuck in futexlock.h
My C debuging skills are a bit rusty so I hope one of you have some ideas.
/Morten
(gdb) bt #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaf17b2e0d in futex_get (t=<value optimized out>, type=<value optimized out>, ps=0x7fffafb7d7a0) at ../../mem/../futexlock.h:113 #2 publ_cback_func (t=<value optimized out>, type=<value optimized out>, ps=0x7fffafb7d7a0) at send_publish.c:272 #3 0x00002acaeeb97815 in run_trans_callbacks_internal (cb_lst=0x2acaf3cfd260, type=256, trans=0x2acaf3cfd1f0, params=0x7fffafb7d7a0) at t_hooks.c:290 #4 0x00002acaeeb97a6e in run_trans_callbacks (type=0, trans=0x2, req=0x0, rpl=0x246, code=0) at t_hooks.c:317 #5 0x00002acaeebbfcb3 in local_reply (t=0x2acaf3cfd1f0, p_msg=<value optimized out>, branch=0, msg_status=<value optimized out>, cancel_bitmap=<value optimized out>) at t_reply.c:1847 #6 0x00002acaeebc29e8 in reply_received (p_msg=0x8d36c8) at t_reply.c:2133 #7 0x000000000044780e in forward_reply (msg=0x8d36c8) at forward.c:689 #8 0x000000000047ff02 in receive_msg ( buf=0x874a40 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 178.21.248.8;branch=z9hG4bKcd3a.d99d6403.0\r\nTo: sip:+380432571592@sip.uni-tel.dk;user=phone;tag=4e546d1f8c10c6f99af9c51d895c9c87-c9ca\r\nFrom: sip:+380432571592@sip.uni-"..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:257 #9 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #10 0x0000000000455cdf in main_loop () at main.c:1447 #11 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
(gdb) bt #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaeeb7ea32 in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:100 #2 _lock (i=<value optimized out>) at lock.h:98 #3 lock_hash (i=<value optimized out>) at h_table.c:98 #4 0x00002acaeeba1b99 in t_lookup_request (p_msg=0x8d36c8, leave_new_locked=0, cancel=0x7fffafb7d5e0) at t_lookup.c:548 #5 0x00002acaeeba3532 in t_check_msg (p_msg=0x8d36c8, param_branch=<value optimized out>) at t_lookup.c:1104 #6 0x00002acaeebab7b1 in t_check_trans (msg=0x2acaf1f4b2e8, foo=<value optimized out>, bar=0x2 <Address 0x2 out of bounds>) at tm.c:1881 #7 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8a6f98, msg=0x8d36c8) at action.c:860 #8 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 #9 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 #10 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 #11 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #12 0x0000000000455cdf in main_loop () at main.c:1447 #13 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
#0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaeeb7ea32 in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:100 #2 _lock (i=<value optimized out>) at lock.h:98 #3 lock_hash (i=<value optimized out>) at h_table.c:98 #4 0x00002acaeeba1b99 in t_lookup_request (p_msg=0x8d36c8, leave_new_locked=0, cancel=0x7fffafb7d5e0) at t_lookup.c:548 #5 0x00002acaeeba3532 in t_check_msg (p_msg=0x8d36c8, param_branch=<value optimized out>) at t_lookup.c:1104 #6 0x00002acaeebab7b1 in t_check_trans (msg=0x2acaf1f4b2e8, foo=<value optimized out>, bar=0x2 <Address 0x2 out of bounds>) at tm.c:1881 #7 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8a6f98, msg=0x8d36c8) at action.c:860 #8 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 #9 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 #10 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 #11 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #12 0x0000000000455cdf in main_loop () at main.c:1447 #13 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
(gdb) bt #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaeeb7e9fa in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:113 #2 _lock (i=<value optimized out>) at lock.h:98 #3 lock_hash (i=<value optimized out>) at h_table.c:98 #4 0x00002acaeebca0e3 in t_uac_prepare (uac_r=0x7fffafb7c270, dst_req=0x7fffafb7c060, dst_cell=0x7fffafb7c058) at uac.c:319 #5 0x00002acaeebcb4ae in t_uac_with_ids (uac_r=0x2acaf1f4b2e8, ret_index=0x0, ret_label=0x0) at uac.c:531 #6 0x00002acaeebcc9c7 in request (uac_r=0x7fffafb7c270, ruri=0x11, to=0x1b, from=0x8e0fe0, next_hop=0x2acaf19c01c0) at uac.c:778 #7 0x00002acaf17af3ff in send_publish (publ=<value optimized out>) at send_publish.c:556 #8 0x00002acaf19c4f67 in dialog_publish (state=<value optimized out>, entity=<value optimized out>, peer=<value optimized out>, callid=<value optimized out>, initiator=<value optimized out>, lifetime=43200, localtag=0x0, remotetag=0x0, localtarget=0x0, remotetarget=0x0) at dialog_publish.c:349 #9 0x00002acaf19c6880 in __dialog_created (dlg=0x2acaf575eb38, type=<value optimized out>, _params=<value optimized out>) at pua_dialoginfo.c:351 #10 0x00002acaf134ef0f in run_create_callbacks (dlg=0x2acaf575eb38, msg=<value optimized out>) at dlg_cb.c:230 #11 0x00002acaf13563c7 in dlg_new_dialog (msg=0x8d36c8, t=0x2acaf157d940) at dlg_handlers.c:643 #12 0x00002acaeeb9751a in run_reqin_callbacks_internal (hl=0x2acaf1e55018, trans=0x2acaf6fa1630, params=0x2acaeede2920) at t_hooks.c:376 #13 0x00002acaeeb7ec5a in build_cell (p_msg=0x8d36c8) at h_table.c:346 #14 0x00002acaeeba240e in new_t (p_msg=0x8d36c8) at t_lookup.c:1332 #15 t_newtran (p_msg=0x8d36c8) at t_lookup.c:1472 #16 0x00002acaeeb8d92b in t_relay_to (p_msg=0x2acaf1f4b2e8, proxy=0x0, proto=0, replicate=0) at t_funcs.c:272 #17 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8c8918, msg=0x8d36c8) at action.c:860 #18 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x8c8918, msg=0x8d36c8) at action.c:1293 #19 0x0000000000496815 in rval_get_int (h=0x2acaf1f4b2e8, msg=0x0, i=0x7fffafb7d1ac, rv=0xffffffffffffffff, cache=0x0) at rvalue.c:897 #20 0x000000000049b68c in rval_expr_eval_int (h=0x7fffafb7dab0, msg=0x8d36c8, res=0x7fffafb7d1ac, rve=0x8c8a08) at rvalue.c:1837 #21 0x000000000049b73d in rval_expr_eval_int (h=0x7fffafb7dab0, msg=0x8d36c8, res=0x7fffafb7d5b8, rve=0x8c90d8) at rvalue.c:1844 #22 0x0000000000411d16 in do_action (h=0x7fffafb7dab0, a=0x8c9928, msg=0x8d36c8) at action.c:834 #23 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x8bda00, msg=0x8d36c8) at action.c:1293 #24 0x0000000000413054 in do_action (h=0x7fffafb7dab0, a=0x8bd7f0, msg=0x8d36c8) at action.c:479 #25 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 #26 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 #27 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia : SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 #28 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #29 0x0000000000455cdf in main_loop () at main.c:1447 #30 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
(gdb) bt full #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 No symbol table info available. #1 0x00002acaeeb7ea32 in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:100 v = <value optimized out> #2 _lock (i=<value optimized out>) at lock.h:98 No locals. #3 lock_hash (i=<value optimized out>) at h_table.c:98 No locals. #4 0x00002acaeeba1b99 in t_lookup_request (p_msg=0x8d36c8, leave_new_locked=0, cancel=0x7fffafb7d5e0) at t_lookup.c:548 p_cell = <value optimized out> isACK = 0 t_msg = <value optimized out> branch = 0xfffffffffffffffc match_status = <value optimized out> hash_bucket = <value optimized out> #5 0x00002acaeeba3532 in t_check_msg (p_msg=0x8d36c8, param_branch=<value optimized out>) at t_lookup.c:1104 local_branch = 0 canceled = 9042808 ret = <value optimized out> #6 0x00002acaeebab7b1 in t_check_trans (msg=0x2acaf1f4b2e8, foo=<value optimized out>, bar=0x2 <Address 0x2 out of bounds>) at tm.c:1881 t = <value optimized out> #7 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8a6f98, msg=0x8d36c8) at action.c:860 ret = -5 v = <value optimized out> dst = {send_sock = 0x2acaedccc000, to = {s = {sa_family = 37544, sa_data = "\220\000\000\000\000\000`\253\220\000\000\000\000"}, sin = { sin_family = 37544, sin_port = 144, sin_addr = {s_addr = 0}, sin_zero = "`\253\220\000\000\000\000"}, sin6 = {sin6_family = 37544, sin6_port = 144, sin6_flowinfo = 0, sin6_addr = {in6_u = {u6_addr8 = "`\253\220\000\000\000\000\000LK\207\000\000\000\000", u6_addr16 = { 43872, 144, 0, 0, 19276, 135, 0, 0}, u6_addr32 = {9481056, 0, 8866636, 0}}}, sin6_scope_id = 9480096}}, id = 0, proto = -46 '\322', send_flags = 74 'J'} tmp = <value optimized out> new_uri = <value optimized out> end = <value optimized out> crt = <value optimized out> f = 0xfffffffffffffffc len = <value optimized out> user = <value optimized out> uri = {user = {s = 0x7fffafb7da60 "\310\066\215", len = 0}, passwd = {s = 0x7fffafb7da40 "\001", len = 5767096}, host = { s = 0x1be1460 "8*\225\233\062", len = -1684723232}, port = {s = 0x100000000 <Address 0x100000000 out of bounds>, len = 134}, params = { s = 0x0, len = 29234864}, sip_params = {s = 0x100000000 <Address 0x100000000 out of bounds>, len = -1687727470}, headers = { s = 0x36b7 <Address 0x36b7 out of bounds>, len = 8208}, port_no = 24939, proto = 24941, type = 1869180009, flags = 21, transport = { ---Type <return> to continue, or q <return> to quit--- s = 0x1be1460 "8*\225\233\062", len = 0}, ttl = {s = 0x0, len = 21}, user_param = {s = 0x1be1460 "8*\225\233\062", len = 21}, maddr = { s = 0x0, len = -1346905536}, method = {s = 0x57ffb8 "%s: %sERROR: forward_reply: no 2nd via found in reply\n", len = -1687738517}, lr = { s = 0x18 <Address 0x18 out of bounds>, len = 21}, r2 = {s = 0x15 <Address 0x15 out of bounds>, len = 29234272}, transport_val = { s = 0x15 <Address 0x15 out of bounds>, len = 21}, ttl_val = {s = 0x1be1460 "8*\225\233\062", len = -1687354197}, user_param_val = { s = 0x2a00000033 <Address 0x2a00000033 out of bounds>, len = 5458017}, maddr_val = {s = 0x6f00000003 <Address 0x6f00000003 out of bounds>, len = 2}, method_val = {s = 0x1 <Address 0x1 out of bounds>, len = 7200}, lr_val = {s = 0x1bacb40 "CEST", len = 5267113}, r2_val = { s = 0x90a606 "", len = -1346905500}} next_hop = {user = {s = 0x10 <Address 0x10 out of bounds>, len = -1687029130}, passwd = {s = 0x1ff4 <Address 0x1ff4 out of bounds>, len = -1687023672}, host = {s = 0x8 <Address 0x8 out of bounds>, len = 29234892}, port = { s = 0x1be16cc "16:42:57 /usr/local/sbin/kamailio[14007]: WARNING: <script>: ua=CEC-PBX", len = -1684723232}, params = {s = 0x329b952a00 "", len = -1684723200}, sip_params = {s = 0x2acaf3e05470 "", len = -1684723144}, headers = {s = 0x329b94fae0 "@íen = -1346905792}, port_no = 16, proto = 0, type = 48, flags = 2948061504, transport = {s = 0x7fffafb7d880 "", len = 29235008}, ttl = { s = 0x1e8c0 <Address 0x1e8c0 out of bounds>, len = 29243072}, user_param = {s = 0x329b722698 "double free or corruption (out)", len = 117056}, maddr = {s = 0x329b9529e0 "", len = -1687739828}, method = {s = 0x329b9535a0 "", len = 5767096}, lr = { s = 0x1 <Address 0x1 out of bounds>, len = -1687631697}, r2 = {s = 0x7fffafb7dad8 "\330", <incomplete sequence \370\211>, len = 8231792}, transport_val = {s = 0x7fffafb7dd8c "\020", len = -289787385}, ttl_val = {s = 0x8d36c8 "\033x\r", len = 412}, user_param_val = { s = 0x313500000000 <Address 0x313500000000 out of bounds>, len = 29243072}, maddr_val = {s = 0x2010 <Address 0x2010 out of bounds>, len = 134}, method_val = {s = 0x2010 <Address 0x2010 out of bounds>, len = 29234864}, lr_val = {s = 0x90 <Address 0x90 out of bounds>, len = -1687731159}, r2_val = {s = 0x3000000010 <Address 0x3000000010 out of bounds>, len = -1684723232}} u = <value optimized out> port = <value optimized out> i = <value optimized out> flags = <value optimized out> sct = <value optimized out> sjt = <value optimized out> rve = <value optimized out> mct = <value optimized out> rv = <value optimized out> rv1 = <value optimized out> c1 = {cache_type = 8866741, val_type = RV_NONE, c = {avp_val = {n = 133, s = {s = 0x85 <Address 0x85 out of bounds>, len = 29234880}, re = 0x85}, pval = {rs = {s = 0x85 <Address 0x85 out of bounds>, len = 29234880}, ri = 1303224171, flags = 0}}} #8 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 t = 0x8a6f98 ret = 1 mod = <value optimized out> #9 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 ctx = {rec_lev = 1, run_flags = 0, last_retcode = -1, jmp_env = {{__jmpbuf = {9254600, -7918255915006962580, 0, 9042136, 9482320, 140736141450636, -7918229962976915956, -7918255915011241414}, __mask_was_saved = 0, __saved_mask = {__val = {9254600, 2, 5317260, 928, 8866420, 0, 8866368, 9254608, 1, 140736141450528, 9254600, 8866429, 5321012, 9479616, 47051076858778, 9295328}}}}} p = 0x7fffafb7dab0 ---Type <return> to continue, or q <return> to quit--- ret = <value optimized out> sfbk = 0 #10 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 msg = 0x0 ctx = {rec_lev = 9034719, run_flags = 0, last_retcode = 9295720, jmp_env = {{__jmpbuf = {47051129731136, 8, 47051127553476, 2, 217355168616, 47051061455248, 47051127553501, 4294967295}, __mask_was_saved = -236996544, __saved_mask = {__val = {8230504, 9007856, 16, 9482320, 140736141450636, 0, 217350982997, 1, 0, 8963168, 47051127486569, 217355168616, 2, 150476210, 217351006434, 0}}}}} ret = <value optimized out> inb = { s = 0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len = 928} #11 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 len = 928 tmp = <value optimized out> from = <value optimized out> fromlen = 16 ri = {src_ip = {af = 2, len = 4, u = {addrl = {351802802, 420}, addr32 = {351802802, 0, 420, 0}, addr16 = {5554, 5368, 0, 0, 420, 0, 0, 0}, addr = "\262\025\370\024\000\000\000\000\244\001\000\000\000\000\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {150476210, 0}, addr32 = {150476210, 0, 0, 0}, addr16 = {5554, 2296, 0, 0, 0, 0, 0, 0}, addr = "\262\025\370\b", '\000' <repeats 11 times>}}, src_port = 5060, dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023IJ\025\370\024\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 351802802}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 351802802, 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 = 0x8972f0, proto = 1 '\001'} buf = "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."... #12 0x0000000000455cdf in main_loop () at main.c:1447 i = 2 pid = <value optimized out> si = 0x8972f0 si_desc = "udp receiver child=2 sock=178.21.248.8:5060\000\000\000\000\000\004", '\000' <repeats 11 times>, "\001", '\000' <repeats 11 times>, "\b\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\004", '\000' <repeats 23 times>"\350, \337\267\257\377\177\000\000\252\267H\000\000\000\000" #13 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251 cfg_stream = 0x1b95010 c = <value optimized out> r = <value optimized out> tmp = 0x7fffafb7ef76 "" ---Type <return> to continue, or q <return> to quit--- tmp_len = 16777216 port = 0 proto = 0 ret = <value optimized out> seed = 524492455 rfd = <value optimized out> debug_save = 0 debug_flag = 0 dont_fork_cnt = 0 n_lst = 0x0
On Thu, Apr 7, 2011 at 10:52 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:
Hello,
do you get high CPU usage by kamailio?
What you can do is to attach with gdb to kamailio processes and see what they are doing:
gdb /path/to/kamailio pid_of_a_kamailio_process bt
You should attach to the sip worker processes - you can find the type of processes with 'kamctl ps'.
Cheers, Daniel
On 4/7/11 9:02 PM, Morten Isaksen wrote:
Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING:
<script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size. Any ideas what it could be, or how to investegate further? I think my next steps would be to increase the private memory og to increase children=4 to children=8
-- Daniel-Constantin Mierla http://www.asipto.com
Hello,
thanks for feedback. Going to work on it asap.
Cheers, Daniel
On 4/19/11 10:17 PM, Morten Isaksen wrote:
Hi,
It happend again.
I got the result from gdb. Here is the output from a bt indside gdb for each worker and one bt full for one of the workers.
They are all stuck in futexlock.h
My C debuging skills are a bit rusty so I hope one of you have some ideas.
/Morten
(gdb) bt #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaf17b2e0d in futex_get (t=<value optimized out>, type=<value optimized out>, ps=0x7fffafb7d7a0) at ../../mem/../futexlock.h:113 #2 publ_cback_func (t=<value optimized out>, type=<value optimized out>, ps=0x7fffafb7d7a0) at send_publish.c:272 #3 0x00002acaeeb97815 in run_trans_callbacks_internal (cb_lst=0x2acaf3cfd260, type=256, trans=0x2acaf3cfd1f0, params=0x7fffafb7d7a0) at t_hooks.c:290 #4 0x00002acaeeb97a6e in run_trans_callbacks (type=0, trans=0x2, req=0x0, rpl=0x246, code=0) at t_hooks.c:317 #5 0x00002acaeebbfcb3 in local_reply (t=0x2acaf3cfd1f0, p_msg=<value optimized out>, branch=0, msg_status=<value optimized out>, cancel_bitmap=<value optimized out>) at t_reply.c:1847 #6 0x00002acaeebc29e8 in reply_received (p_msg=0x8d36c8) at t_reply.c:2133 #7 0x000000000044780e in forward_reply (msg=0x8d36c8) at forward.c:689 #8 0x000000000047ff02 in receive_msg ( buf=0x874a40 "SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 178.21.248.8;branch=z9hG4bKcd3a.d99d6403.0\r\nTo: sip:+380432571592@sip.uni-tel.dk;user=phone;tag=4e546d1f8c10c6f99af9c51d895c9c87-c9ca\r\nFrom: sip:+380432571592@sip.uni-"..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:257 #9 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #10 0x0000000000455cdf in main_loop () at main.c:1447 #11 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
(gdb) bt #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaeeb7ea32 in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:100 #2 _lock (i=<value optimized out>) at lock.h:98 #3 lock_hash (i=<value optimized out>) at h_table.c:98 #4 0x00002acaeeba1b99 in t_lookup_request (p_msg=0x8d36c8, leave_new_locked=0, cancel=0x7fffafb7d5e0) at t_lookup.c:548 #5 0x00002acaeeba3532 in t_check_msg (p_msg=0x8d36c8, param_branch=<value optimized out>) at t_lookup.c:1104 #6 0x00002acaeebab7b1 in t_check_trans (msg=0x2acaf1f4b2e8, foo=<value optimized out>, bar=0x2<Address 0x2 out of bounds>) at tm.c:1881 #7 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8a6f98, msg=0x8d36c8) at action.c:860 #8 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 #9 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 #10 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 #11 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #12 0x0000000000455cdf in main_loop () at main.c:1447 #13 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
#0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaeeb7ea32 in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:100 #2 _lock (i=<value optimized out>) at lock.h:98 #3 lock_hash (i=<value optimized out>) at h_table.c:98 #4 0x00002acaeeba1b99 in t_lookup_request (p_msg=0x8d36c8, leave_new_locked=0, cancel=0x7fffafb7d5e0) at t_lookup.c:548 #5 0x00002acaeeba3532 in t_check_msg (p_msg=0x8d36c8, param_branch=<value optimized out>) at t_lookup.c:1104 #6 0x00002acaeebab7b1 in t_check_trans (msg=0x2acaf1f4b2e8, foo=<value optimized out>, bar=0x2<Address 0x2 out of bounds>) at tm.c:1881 #7 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8a6f98, msg=0x8d36c8) at action.c:860 #8 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 #9 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 #10 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: sip:178.21.248.20;lr;ftag=as3d313976\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 #11 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #12 0x0000000000455cdf in main_loop () at main.c:1447 #13 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
(gdb) bt #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 #1 0x00002acaeeb7e9fa in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:113 #2 _lock (i=<value optimized out>) at lock.h:98 #3 lock_hash (i=<value optimized out>) at h_table.c:98 #4 0x00002acaeebca0e3 in t_uac_prepare (uac_r=0x7fffafb7c270, dst_req=0x7fffafb7c060, dst_cell=0x7fffafb7c058) at uac.c:319 #5 0x00002acaeebcb4ae in t_uac_with_ids (uac_r=0x2acaf1f4b2e8, ret_index=0x0, ret_label=0x0) at uac.c:531 #6 0x00002acaeebcc9c7 in request (uac_r=0x7fffafb7c270, ruri=0x11, to=0x1b, from=0x8e0fe0, next_hop=0x2acaf19c01c0) at uac.c:778 #7 0x00002acaf17af3ff in send_publish (publ=<value optimized out>) at send_publish.c:556 #8 0x00002acaf19c4f67 in dialog_publish (state=<value optimized out>, entity=<value optimized out>, peer=<value optimized out>, callid=<value optimized out>, initiator=<value optimized out>, lifetime=43200, localtag=0x0, remotetag=0x0, localtarget=0x0, remotetarget=0x0) at dialog_publish.c:349 #9 0x00002acaf19c6880 in __dialog_created (dlg=0x2acaf575eb38, type=<value optimized out>, _params=<value optimized out>) at pua_dialoginfo.c:351 #10 0x00002acaf134ef0f in run_create_callbacks (dlg=0x2acaf575eb38, msg=<value optimized out>) at dlg_cb.c:230 #11 0x00002acaf13563c7 in dlg_new_dialog (msg=0x8d36c8, t=0x2acaf157d940) at dlg_handlers.c:643 #12 0x00002acaeeb9751a in run_reqin_callbacks_internal (hl=0x2acaf1e55018, trans=0x2acaf6fa1630, params=0x2acaeede2920) at t_hooks.c:376 #13 0x00002acaeeb7ec5a in build_cell (p_msg=0x8d36c8) at h_table.c:346 #14 0x00002acaeeba240e in new_t (p_msg=0x8d36c8) at t_lookup.c:1332 #15 t_newtran (p_msg=0x8d36c8) at t_lookup.c:1472 #16 0x00002acaeeb8d92b in t_relay_to (p_msg=0x2acaf1f4b2e8, proxy=0x0, proto=0, replicate=0) at t_funcs.c:272 #17 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8c8918, msg=0x8d36c8) at action.c:860 #18 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x8c8918, msg=0x8d36c8) at action.c:1293 #19 0x0000000000496815 in rval_get_int (h=0x2acaf1f4b2e8, msg=0x0, i=0x7fffafb7d1ac, rv=0xffffffffffffffff, cache=0x0) at rvalue.c:897 #20 0x000000000049b68c in rval_expr_eval_int (h=0x7fffafb7dab0, msg=0x8d36c8, res=0x7fffafb7d1ac, rve=0x8c8a08) at rvalue.c:1837 #21 0x000000000049b73d in rval_expr_eval_int (h=0x7fffafb7dab0, msg=0x8d36c8, res=0x7fffafb7d5b8, rve=0x8c90d8) at rvalue.c:1844 #22 0x0000000000411d16 in do_action (h=0x7fffafb7dab0, a=0x8c9928, msg=0x8d36c8) at action.c:834 #23 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x8bda00, msg=0x8d36c8) at action.c:1293 #24 0x0000000000413054 in do_action (h=0x7fffafb7dab0, a=0x8bd7f0, msg=0x8d36c8) at action.c:479 #25 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 #26 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 #27 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route:sip:178.21.248.20;lr;ftag=as3d313976\r\nVia : SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 #28 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 #29 0x0000000000455cdf in main_loop () at main.c:1447 #30 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251
(gdb) bt full #0 0x000000329b6d0a19 in syscall () from /lib64/libc.so.6 No symbol table info available. #1 0x00002acaeeb7ea32 in futex_get (i=<value optimized out>) at ../../mem/../futexlock.h:100 v =<value optimized out> #2 _lock (i=<value optimized out>) at lock.h:98 No locals. #3 lock_hash (i=<value optimized out>) at h_table.c:98 No locals. #4 0x00002acaeeba1b99 in t_lookup_request (p_msg=0x8d36c8, leave_new_locked=0, cancel=0x7fffafb7d5e0) at t_lookup.c:548 p_cell =<value optimized out> isACK = 0 t_msg =<value optimized out> branch = 0xfffffffffffffffc match_status =<value optimized out> hash_bucket =<value optimized out> #5 0x00002acaeeba3532 in t_check_msg (p_msg=0x8d36c8, param_branch=<value optimized out>) at t_lookup.c:1104 local_branch = 0 canceled = 9042808 ret =<value optimized out> #6 0x00002acaeebab7b1 in t_check_trans (msg=0x2acaf1f4b2e8, foo=<value optimized out>, bar=0x2<Address 0x2 out of bounds>) at tm.c:1881 t =<value optimized out> #7 0x000000000041345c in do_action (h=0x7fffafb7dab0, a=0x8a6f98, msg=0x8d36c8) at action.c:860 ret = -5 v =<value optimized out> dst = {send_sock = 0x2acaedccc000, to = {s = {sa_family = 37544, sa_data = "\220\000\000\000\000\000`\253\220\000\000\000\000"}, sin = { sin_family = 37544, sin_port = 144, sin_addr = {s_addr = 0}, sin_zero = "`\253\220\000\000\000\000"}, sin6 = {sin6_family = 37544, sin6_port = 144, sin6_flowinfo = 0, sin6_addr = {in6_u = {u6_addr8 = "`\253\220\000\000\000\000\000LK\207\000\000\000\000", u6_addr16 = { 43872, 144, 0, 0, 19276, 135, 0, 0}, u6_addr32 = {9481056, 0, 8866636, 0}}}, sin6_scope_id = 9480096}}, id = 0, proto = -46 '\322', send_flags = 74 'J'} tmp =<value optimized out> new_uri =<value optimized out> end =<value optimized out> crt =<value optimized out> f = 0xfffffffffffffffc len =<value optimized out> user =<value optimized out> uri = {user = {s = 0x7fffafb7da60 "\310\066\215", len = 0}, passwd = {s = 0x7fffafb7da40 "\001", len = 5767096}, host = { s = 0x1be1460 "8*\225\233\062", len = -1684723232}, port = {s = 0x100000000<Address 0x100000000 out of bounds>, len = 134}, params = { s = 0x0, len = 29234864}, sip_params = {s = 0x100000000
<Address 0x100000000 out of bounds>, len = -1687727470}, headers = { s = 0x36b7<Address 0x36b7 out of bounds>, len = 8208}, port_no = 24939, proto = 24941, type = 1869180009, flags = 21, transport = { ---Type<return> to continue, or q<return> to quit--- s = 0x1be1460 "8*\225\233\062", len = 0}, ttl = {s = 0x0, len = 21}, user_param = {s = 0x1be1460 "8*\225\233\062", len = 21}, maddr = { s = 0x0, len = -1346905536}, method = {s = 0x57ffb8 "%s: %sERROR: forward_reply: no 2nd via found in reply\n", len = -1687738517}, lr = { s = 0x18<Address 0x18 out of bounds>, len = 21}, r2 = {s = 0x15<Address 0x15 out of bounds>, len = 29234272}, transport_val = { s = 0x15<Address 0x15 out of bounds>, len = 21}, ttl_val = {s = 0x1be1460 "8*\225\233\062", len = -1687354197}, user_param_val = { s = 0x2a00000033<Address 0x2a00000033 out of bounds>, len = 5458017}, maddr_val = {s = 0x6f00000003<Address 0x6f00000003 out of bounds>, len = 2}, method_val = {s = 0x1<Address 0x1 out of bounds>, len = 7200}, lr_val = {s = 0x1bacb40 "CEST", len = 5267113}, r2_val = { s = 0x90a606 "", len = -1346905500}} next_hop = {user = {s = 0x10<Address 0x10 out of bounds>, len = -1687029130}, passwd = {s = 0x1ff4<Address 0x1ff4 out of bounds>, len = -1687023672}, host = {s = 0x8<Address 0x8 out of bounds>, len = 29234892}, port = { s = 0x1be16cc "16:42:57 /usr/local/sbin/kamailio[14007]: WARNING:<script>: ua=CEC-PBX", len = -1684723232}, params = {s = 0x329b952a00 "", len = -1684723200}, sip_params = {s = 0x2acaf3e05470 "", len = -1684723144}, headers = {s = 0x329b94fae0 "@íen = -1346905792}, port_no = 16, proto = 0, type = 48, flags = 2948061504, transport = {s = 0x7fffafb7d880 "", len = 29235008}, ttl = { s = 0x1e8c0<Address 0x1e8c0 out of bounds>, len = 29243072}, user_param = {s = 0x329b722698 "double free or corruption (out)", len = 117056}, maddr = {s = 0x329b9529e0 "", len = -1687739828}, method = {s = 0x329b9535a0 "", len = 5767096}, lr = { s = 0x1<Address 0x1 out of bounds>, len = -1687631697}, r2 = {s = 0x7fffafb7dad8 "\330",<incomplete sequence \370\211>, len = 8231792}, transport_val = {s = 0x7fffafb7dd8c "\020", len = -289787385}, ttl_val = {s = 0x8d36c8 "\033x\r", len = 412}, user_param_val = { s = 0x313500000000<Address 0x313500000000 out of bounds>, len = 29243072}, maddr_val = {s = 0x2010<Address 0x2010 out of bounds>, len = 134}, method_val = {s = 0x2010<Address 0x2010 out of bounds>, len = 29234864}, lr_val = {s = 0x90<Address 0x90 out of bounds>, len = -1687731159}, r2_val = {s = 0x3000000010<Address 0x3000000010 out of bounds>, len = -1684723232}} u =<value optimized out> port =<value optimized out> i =<value optimized out> flags =<value optimized out> sct =<value optimized out> sjt =<value optimized out> rve =<value optimized out> mct =<value optimized out> rv =<value optimized out> rv1 =<value optimized out> c1 = {cache_type = 8866741, val_type = RV_NONE, c = {avp_val = {n = 133, s = {s = 0x85<Address 0x85 out of bounds>, len = 29234880}, re = 0x85}, pval = {rs = {s = 0x85<Address 0x85 out of bounds>, len = 29234880}, ri = 1303224171, flags = 0}}} #8 0x0000000000415d2b in run_actions (h=0x7fffafb7dab0, a=0x89f8d8, msg=0x8d36c8) at action.c:1293 t = 0x8a6f98 ret = 1 mod =<value optimized out> #9 0x0000000000416084 in run_top_route (a=0x89f8d8, msg=0x8d36c8, c=<value optimized out>) at action.c:1341 ctx = {rec_lev = 1, run_flags = 0, last_retcode = -1, jmp_env = {{__jmpbuf = {9254600, -7918255915006962580, 0, 9042136, 9482320, 140736141450636, -7918229962976915956, -7918255915011241414}, __mask_was_saved = 0, __saved_mask = {__val = {9254600, 2, 5317260, 928, 8866420, 0, 8866368, 9254608, 1, 140736141450528, 9254600, 8866429, 5321012, 9479616, 47051076858778, 9295328}}}}} p = 0x7fffafb7dab0 ---Type<return> to continue, or q<return> to quit--- ret =<value optimized out> sfbk = 0 #10 0x000000000047ff4c in receive_msg ( buf=0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: <sip:178.21.248.20;lr;ftag=as3d313976>\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len=<value optimized out>, rcv_info=0x7fffafb7dd20) at receive.c:196 msg = 0x0 ctx = {rec_lev = 9034719, run_flags = 0, last_retcode = 9295720, jmp_env = {{__jmpbuf = {47051129731136, 8, 47051127553476, 2, 217355168616, 47051061455248, 47051127553501, 4294967295}, __mask_was_saved = -236996544, __saved_mask = {__val = {8230504, 9007856, 16, 9482320, 140736141450636, 0, 217350982997, 1, 0, 8963168, 47051127486569, 217355168616, 2, 150476210, 217351006434, 0}}}}} ret =<value optimized out> inb = { s = 0x874a40 "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: <sip:178.21.248.20;lr;ftag=as3d313976>\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."..., len = 928} #11 0x00000000005067ab in udp_rcv_loop () at udp_server.c:520 len = 928 tmp =<value optimized out> from =<value optimized out> fromlen = 16 ri = {src_ip = {af = 2, len = 4, u = {addrl = {351802802, 420}, addr32 = {351802802, 0, 420, 0}, addr16 = {5554, 5368, 0, 0, 420, 0, 0, 0}, addr = "\262\025\370\024\000\000\000\000\244\001\000\000\000\000\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {150476210, 0}, addr32 = {150476210, 0, 0, 0}, addr16 = {5554, 2296, 0, 0, 0, 0, 0, 0}, addr = "\262\025\370\b", '\000'<repeats 11 times>}}, src_port = 5060, dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023IJ\025\370\024\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 351802802}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 351802802, 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 = 0x8972f0, proto = 1 '\001'} buf = "INVITE sip:20322595@178.21.248.8:5060;transport=udp SIP/2.0\r\nRecord-Route: <sip:178.21.248.20;lr;ftag=as3d313976>\r\nVia: SIP/2.0/UDP 178.21.248.20;branch=z9hG4bKdd3a.3d0516e1.0\r\nVia: SIP/2.0/UDP 81.27."... #12 0x0000000000455cdf in main_loop () at main.c:1447 i = 2 pid =<value optimized out> si = 0x8972f0 si_desc = "udp receiver child=2 sock=178.21.248.8:5060\000\000\000\000\000\004", '\000'<repeats 11 times>, "\001", '\000'<repeats 11 times>, "\b\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\004", '\000'<repeats 23 times>"\350, \337\267\257\377\177\000\000\252\267H\000\000\000\000" #13 0x0000000000456de2 in main (argc=<value optimized out>, argv=0x7fffafb7dfe8) at main.c:2251 cfg_stream = 0x1b95010 c =<value optimized out> r =<value optimized out> tmp = 0x7fffafb7ef76 "" ---Type<return> to continue, or q<return> to quit--- tmp_len = 16777216 port = 0 proto = 0 ret =<value optimized out> seed = 524492455 rfd =<value optimized out> debug_save = 0 debug_flag = 0 dont_fork_cnt = 0 n_lst = 0x0
On Thu, Apr 7, 2011 at 10:52 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:
Hello,
do you get high CPU usage by kamailio?
What you can do is to attach with gdb to kamailio processes and see what they are doing:
gdb /path/to/kamailio pid_of_a_kamailio_process bt
You should attach to the sip worker processes - you can find the type of processes with 'kamctl ps'.
Cheers, Daniel
On 4/7/11 9:02 PM, Morten Isaksen wrote:
Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING:
<script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size. Any ideas what it could be, or how to investegate further? I think my next steps would be to increase the private memory og to increase children=4 to children=8
-- Daniel-Constantin Mierla http://www.asipto.com
On 04/07/2011 10:02 PM, Morten Isaksen wrote:
Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING:
<script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed
Hello Morten,
Do you have the carrier avp set in the failure route (it is ok if it's set in normal route it should be visible from there)? Also can you paste the lines from failure_route that are around the cr_next_domain . My suspicion is that you have some calls that reach failure route, but because of some particular cfg lines, they are not correctly routed and the daemon just sleeps in some lines of code on each worker.
For replicating the bug and retrieve the line of code where the workers block(as Daniel suggested), it would be better if you decrease the number of worker and keep the same shm memory config value.
Marius
Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size.
Any ideas what it could be, or how to investegate further?
I think my next steps would be to increase the private memory og to increase children=4 to children=8
Hi Marius,
The carrier avp is always set in route[0].
My failure_route looks like this.
xlog("L_WARN", "Failure route - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n"); if (t_check_status("408|404|5[0-9][0-9]|6[0-9][0-9]") && !t_check_status("503")) { revert_uri(); if (!cr_next_domain("$avp(s:carrier)", "$avp(s:domain)", "$rU", "$avp(s:host)", "$T_reply_code", "$avp(s:domain)")) { xlog("L_ERR", "cr_next_domain failed\n"); exit; } if (!cr_route("$avp(s:carrier)", "$avp(s:domain)", "$rU", "$rU", "call_id")) { xlog("L_ERR", "cr_route failed\n"); exit; } $avp(s:host)= $rd; t_on_failure("COREROUTE"); append_branch(); xlog("L_WARN", "Outgoing M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n"); xlog("$si -> $rd"); if (!t_relay()) { xlog("L_ERR", "t_relay failed\n"); exit; }; }
On Fri, Apr 8, 2011 at 11:08 AM, marius zbihlei marius.zbihlei@1and1.ro wrote:
On 04/07/2011 10:02 PM, Morten Isaksen wrote:
Hi!
Kamailio 3.0.3.
I have a strange problem with one of our Kamailio servers. This one is used for routing (with carrierroute) and to send presence information (with pua module)
Once every 10 day or so I get this error and then Kamailio stops responding to any SIP packets.
Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: WARNING:
<script>: Failure route - M=INVITE RURI=sip:8615XXXX@178.XX.XX.XX F=sip:861XXXXX@188.120.93.114:1025 T=sip:86155XXXX@sip1.uni-tel.dk IP=178.XX.XX.XX ID=6de881ec07f9c6494ee589cf208da358@10.11.87.206 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:95]: cannot find AVP 'carrier' Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: carrierroute [cr_func.c:805]: invalid carrier id -1 Apr 6 08:05:48 sip-core-1 /usr/local/sbin/kamailio[9186]: ERROR: <script>: cr_next_domain failed
Hello Morten,
Do you have the carrier avp set in the failure route (it is ok if it's set in normal route it should be visible from there)? Also can you paste the lines from failure_route that are around the cr_next_domain . My suspicion is that you have some calls that reach failure route, but because of some particular cfg lines, they are not correctly routed and the daemon just sleeps in some lines of code on each worker.
For replicating the bug and retrieve the line of code where the workers block(as Daniel suggested), it would be better if you decrease the number of worker and keep the same shm memory config value.
Marius
Shared memory size is 128M and over halv is free just before the error. The server is in production and does handle debug>1 well, so I do not have much information in the log files. Private memory is the default size.
Any ideas what it could be, or how to investegate further?
I think my next steps would be to increase the private memory og to increase children=4 to children=8
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
On 04/09/2011 11:09 AM, Morten Isaksen wrote:
Hi Marius,
Hello,
Thanks for the update, but unfortunately I can't spot anything wrong. As Daniel noted, please send a trace of the worker process (you can also select the worker's pid from the log file)Attack with GDB for several times and issue a bt (or bt full) command. If the traces are different, this will help. Also do a ngrep to see that indeed you have traffic and K is not responding at all.
Marius
The carrier avp is always set in route[0].
My failure_route looks like this.
xlog("L_WARN", "Failure route - M=$rm RURI=$ru F=$fu T=$tuIP=$si ID=$ci\n"); if (t_check_status("408|404|5[0-9][0-9]|6[0-9][0-9]")&& !t_check_status("503")) { revert_uri(); if (!cr_next_domain("$avp(s:carrier)", "$avp(s:domain)", "$rU", "$avp(s:host)", "$T_reply_code", "$avp(s:domain)")) { xlog("L_ERR", "cr_next_domain failed\n"); exit; } if (!cr_route("$avp(s:carrier)", "$avp(s:domain)", "$rU", "$rU", "call_id")) { xlog("L_ERR", "cr_route failed\n"); exit; } $avp(s:host)= $rd; t_on_failure("COREROUTE"); append_branch(); xlog("L_WARN", "Outgoing M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n"); xlog("$si -> $rd"); if (!t_relay()) { xlog("L_ERR", "t_relay failed\n"); exit; }; }
-
Daniel-Constantin Mierla -
marius zbihlei -
Morten Isaksen