Hello,
we use the xmlrpc module to fetch the list of users with the ul_dump MI command. When the
number of users increased, this started to fail as the output size grew. Apparently this
is because of too small write queue sizes (tcp_conn_wq_max). I discussed increasing the
tcp_conn_wq_max setting with a coworker, who was reluctant to change it as it would affect
SIP over TCP as well. We would probably also have to increase it if we hit the limit again
at a later time. What we would like to know is if there's a way around this without
having to fiddle with buffer sizes (or if this behavior is considered a bug).
We originally used the mi_xmlrpc module, but changed to the xmlrpc module as the former
made kamailio spawn zombie processes on xmlrpc requests (which is considered a bug I
guess).
FWIW, here's the log from a failed request, running kamailio 3.3.4:
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [ip_addr.c:247]:
tcpconn_new: new tcp connection: [REMOVED]
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [tcp_main.c:1089]:
tcpconn_new: on port 40261, type 2
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [tcp_main.c:1403]:
tcpconn_add: hashes: 40:3802:373, 326
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [io_wait.h:390]: DBG:
io_watch_add(0x828660, 94, 2, 0x7f2f87f31ca8), fd_no=85
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [io_wait.h:617]: DBG:
io_watch_del (0x828660, 94, -1, 0x0) fd_no=86 called
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [tcp_main.c:4298]:
tcp: DBG: sending to child, events 1
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [tcp_main.c:3969]:
selected tcp worker 5 58(4960) for activity on [tcp:0.0.0.0:8080], 0x7f2f87f31ca8
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_read.c:1358]:
received n=8 con=0x7f2f87f31ca8, fd=10
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_read.c:1168]:
tcp_read_req: content-length= 153
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:624]: SIP Request:
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:626]: method: <POST>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:628]: uri: </RPC2>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:630]: version: <HTTP/1.0>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:202]: DEBUG: get_hdr_body : content_length=153
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:104]: found end of header
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [receive.c:149]:
After parse_msg...
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: xmlrpc [xmlrpc.c:2273]: new fake
xml msg created (355 bytes):#012<POST sip:127.0.0.1:9 HTTP/1.0#015#012Via: SIP/2.0/TCP
[REMOVED]:40261#015#012Host: [REMOVED]:8080#015#012User-Agent: xmlrpclib.py/1.0.1 (by
www.pythonware.com)#015#012Content-Type: text/xml#015#012Content-Length:
153#015#012#015#012<?xml
version='1.0'?>#012<methodCall>#012<methodName>mi</methodName>#012<params>#012<param>#012<value><string>ul_dump</string></value>#012</param>#012</params>#012</methodCall>#012>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:624]: SIP Request:
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:626]: method: <POST>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:628]: uri: <sip:127.0.0.1:9>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:630]: version: <HTTP/1.0>
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/parse_via.c:2561]: end of header reached, state=5
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:511]: parse_headers: Via found, flags=2
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:513]: parse_headers: this is the first via
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:202]: DEBUG: get_hdr_body : content_length=153
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[parser/msg_parser.c:104]: found end of header
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core>
[msg_translator.c:206]: check_via_address([REMOVED], [REMOVED], 0)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: sl [sl_funcs.c:499]: execute
callback for event type 1
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: siptrace [siptrace.c:1343]: trace
off...
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_main.c:2316]:
tcp_send: send from reader (4960 (58)), reusing fd
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_main.c:2552]:
tcp_send: sending...
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_main.c:2586]:
tcp_send: after real write: c= 0x7f2f87f31ca8 n=15928 fd=10
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_main.c:2587]:
tcp_send: buf=[REMOVED]
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: ERROR: <core> [tcp_main.c:708]:
ERROR: wbufq_add(64634 bytes): write queue full or timeout (0, total 0, last write
6648472 s ago)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: ERROR: sl [../../forward.h:171]:
msg_send: ERROR: tcp_send failed
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: ERROR: xmlrpc [xmlrpc.c:804]: Error while
sending reply
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [tcp_main.c:3620]:
handle_ser_child: read response= 7f2f87f31ca8, -2, fd -1 from 58 (4960)
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: ERROR: <core> [tcp_main.c:3634]:
handle_ser_child: ERROR: received CON_ERROR for 0x7f2f87f31ca8 (id 7494), refcnt 3, flags
0x4018
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: xmlrpc [xmlrpc.c:2194]: xmlrpc:
error while trying script
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [usr_avp.c:644]:
DEBUG:destroy_avp_list: destroying list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [usr_avp.c:644]:
DEBUG:destroy_avp_list: destroying list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [usr_avp.c:644]:
DEBUG:destroy_avp_list: destroying list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [usr_avp.c:644]:
DEBUG:destroy_avp_list: destroying list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [usr_avp.c:644]:
DEBUG:destroy_avp_list: destroying list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [usr_avp.c:644]:
DEBUG:destroy_avp_list: destroying list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [xavp.c:365]:
destroying xavp list (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_read.c:1285]:
releasing con 0x7f2f87f31ca8, state -2, fd=10, id=7494
Apr 1 23:38:24 server /usr/sbin/kamailio[4960]: DEBUG: <core> [tcp_read.c:1286]:
extra_data (nil)
Apr 1 23:38:24 server /usr/sbin/kamailio[4982]: DEBUG: <core> [tcp_main.c:3381]:
handle_tcp_child: reader response= 7f2f87f31ca8, -2 from 5
Thanks,
Jon