[SR-Users] Kamailio stops processing requests over UDP

[Juha Heinanen]

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