[SR-Users] Kamailio stops processing requests over UDP

Thu Aug 29 09:48:28 CEST 2019

Can you see what is the next debug message printed by pid 19674?

If you have access to the system when that blocks in this way during
that interval, take the output of 'kamctl trap' or the backtrace with
gdb for a sip udp worker process.

Cheers,
Daniel

On 29.08.19 08:50, Juha Heinanen wrote:
> During the UDP freeze, ss shows:
>
> udp    UNCONN     429312 0      x.x.x.x:5060 *:*
> tcp    LISTEN     0      128    x.x.x.x:5060 *:*
>
> i.e., there is lots of bytes in UDP receive queue, which K has not
> picked up.
>
> I don't see anything special in debug log when the udp freeze started at
> about 08:31:15.  Below is debug log when the last request over udp was
> processed.  After that no requests over udp were processed until about
> 10 minutes later. The options request processed at 08:31:38 came over
> tcp.
>
> What can cause UDP workers from not picking up requests from the receive
> queue?
>
> K is here running on Debian Stretch virtual machine.
>
> -- Juha
>
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (106/100/516) [[SIP/2.0 480 Request Terminated 0D  0A Via: SIP/2.0/UDP x.x.x.x;branch=z9hG4bK77ac.4ef023a18a4e088ff54]]
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status):
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:622]: parse_msg():  version: <SIP/2.0>
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:624]: parse_msg():  status:  <480>
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:626]: parse_msg():  reason:  <Request Terminated>
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK77ac.4ef023a18a4e088ff54d3011a49d2566.0>; state=16
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKco9p4lg74s9h8t8ql3nrqeeb60>; state=16
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=78
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:511]: parse_headers(): this is the second via
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=mh8iDJcH5U8.
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [69]; uri=[sip:+nnnnnn at x.x.x.x:5060;user=phone]
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [<sip:+nnnnnn at x.x.x.x:5060;user=phone>], to tag [mh8iDJcH5U8.]
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE>
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: <core> [core/receive.c:241]: receive_msg(): --- received sip message - reply - call-id: [SDm882f01-3268f8b9028f4a395a9cb72379c4b423-ao92gd1] - cseq: [1 INVITE]
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: tm [t_lookup.c:1041]: t_check_msg(): msg (0x7fd7cd1278a0) id=7999/19674 global id=7998/19674 T start=(nil)
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: tm [t_lookup.c:919]: t_reply_matching(): t_reply_matching: hash 51831 label 0 branch 0
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: tm [t_lookup.c:974]: t_reply_matching(): reply (0x7fd7cd1278a0) matched an active transaction (T=0x7fd7b443ead0)!
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7fd7b443ead0, callback type 2, id 0 entered
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: acc [acc_logic.c:681]: tmcb_func(): acc callback called for t(0x7fd7b443ead0) event type 2, reply code 480
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: acc [acc_logic.c:413]: should_acc_reply(): probing acc state - code: 480 flags: 0x240005c4
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: acc [acc_logic.c:430]: should_acc_reply(): failed acc is on
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: tm [t_lookup.c:1111]: t_check_msg(): msg (0x7fd7cd1278a0) id=7999/19674 global id=7999/19674 T end=0x7fd7b443ead0
> Aug 28 08:31:15 rox2 /usr/bin/sip-proxy[19674]: DEBUG: tm [t_reply.c:2243]: reply_received(): transaction found - T:0x7fd7b443ead0 branch:0
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19711]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x560ad2dc4100, 73, -1, 0x0) fd_no=56 called
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19711]: DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19711]: DEBUG: <core> [core/tcp_main.c:3847]: send2child(): checking per-socket generic workers (19699/27..19706/34) [tcp:x.x.x.x:5060]
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19711]: DEBUG: <core> [core/tcp_main.c:3875]: send2child(): selected tcp worker idx:0 proc:27 pid:19699 for activity on [tcp:x.x.x.x:5060], 0x7fd7b4715da0
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/tcp_read.c:1759]: handle_io(): received n=8 con=0x7fd7b4715da0, fd=20
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/tcp_read.c:1560]: tcp_read_req(): content-length=0
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg():  method:  <OPTIONS>
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg():  uri:     <sip:x.x.x.x>
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg():  version: <SIP/2.0>
> Aug 28 08:31:38 rox2 /usr/bin/sip-proxy[19699]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK7ad16a0b>; state=16
>
> _______________________________________________
> Kamailio (SER) - Users Mailing List
> sr-users at lists.kamailio.org
> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda