[SR-Users] Buffer size with xmlrpc module

Tue Apr 16 11:27:00 CEST 2013

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