[OpenSIPS-Users] tcp io logs, loop

Dawid Mielnik dawid.mielnik at gmail.com
Wed Nov 2 22:16:36 CET 2016 

Hi,

I have a reduntant OpenSIPS 2.2.1 setup with clusterer and binary interface
replication. TCP is not used for SIP. A few times I have observed debug log
being flooded with messages like these below.
What is causing them ? Should I be worried ? How to get rid of this issue ?

Oct 17 11:25:56.281436 DEB 4315  DBG:maxfwd:is_maxfwd_present: value = 70
Oct 17 11:25:56.281481 DEB 4315  DBG:uri:has_totag: no totag
Oct 17 11:25:56.281492 DEB 4315  DBG:siptrace:sip_trace_w: can't trace
dialog! Will try to trace transaction
Oct 17 11:25:56.281498 DEB 4315  DBG:siptrace:sip_trace_w: tracing
transaction!
Oct 17 11:25:56.281502 DEB 4315  DBG:core:parse_to_param: tag=as09518802
Oct 17 11:25:56.281507 DEB 4315  DBG:core:parse_to: end of header reached,
state=29
Oct 17 11:25:56.281511 DEB 4315  DBG:core:parse_to: display={"asterisk"},
ruri={sip:asterisk at XX.XX.XXX.253}
Oct 17 11:25:56.281516 DEB 4315  DBG:core:parse_headers: flags=40
Oct 17 11:25:56.281521 DEB 4315  DBG:siptrace:sip_trace: sip_trace called
Oct 17 11:25:56.281525 DEB 4315  DBG:siptrace:pipport2su: proto 17, host
XX.XX.XXX.253 , port 5060
Oct 17 11:25:56.281530 DEB 4315  DBG:siptrace:pipport2su: proto 17, host
XX.XX.XXX.250 , port 5060
Oct 17 11:25:56.281535 DEB 4315  DBG:core:mk_proxy: doing DNS lookup...
Oct 17 11:25:56.281539 DEB 4315  DBG:core:comp_scriptvar: int 20 : 5060 /
5060
Oct 17 11:25:56.281543 DEB 4315  DBG:core:parse_headers:
flags=ffffffffffffffff
Oct 17 11:25:56.281548 DEB 4315  DBG:core:check_ip_address: params
XX.XX.XXX.253, XX.XX.XXX.253, 0
Oct 17 11:25:56.281552 DEB 4315  DBG:core:parse_headers: flags=40
Oct 17 11:25:56.281570 DEB 4315  DBG:siptrace:pipport2su: proto 17, host
XX.XX.XXX.250 , port 5060
Oct 17 11:25:56.281576 DEB 4315  DBG:siptrace:pipport2su: proto 17, host
XX.XX.XXX.253 , port 5060
Oct 17 11:25:56.281581 DEB 4315  DBG:core:mk_proxy: doing DNS lookup...
Oct 17 11:25:56.281664 DEB 4315  DBG:core:destroy_avp_list: destroying list
(nil)
Oct 17 11:25:56.281673 DEB 4315  DBG:core:receive_msg: cleaning up
Oct 17 11:25:58.515305 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.515378 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.515387 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.515792 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.515814 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.515820 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.515825 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.515830 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.515835 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.515840 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.515844 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.515856 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.515861 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.516050 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.516163 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.516187 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.516193 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.516198 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.516203 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.516208 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.516332 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.516343 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.516349 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.516353 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.516358 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.516431 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.516439 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.516445 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.516449 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.516454 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.516459 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.516644 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.516660 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.516666 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.516671 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.516676 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.516739 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.516751 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.516756 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.516760 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.516765 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.516769 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.516826 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.516843 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.516849 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.516854 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.516859 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.516880 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.516886 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.516891 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.516896 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.516918 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.516925 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.516976 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.516984 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.517026 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.517043 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.517049 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.517072 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.517079 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.517084 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.517089 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.517094 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.517098 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.517186 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.517203 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.517209 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.517214 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.517218 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.517354 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.517375 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.517381 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:58.517386 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:58.517405 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:58.517411 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:58.517528 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:58.517545 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:58.517551 DEB 4335  DBG:core:handle_tcpconn_ev: data available
on 0x7f2da0d453c8 48
Oct 17 11:25:58.517556 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index 1 48 (0x83b1c0, 48, 1, 0x0,0x1) fd_no=36 called
Oct 17 11:25:58.517560 DEB 4335  DBG:core:send2child: to tcp child 0
0(4327), 0x7f2da0d453c8 rw 1
Oct 17 11:25:58.517705 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:58.517726 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:58.517732 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221


...


Oct 17 11:25:59.398295 DEB 4327  DBG:core:handle_io: We have received conn
0x7f2da0d453c8 with rw 1 on fd 8
Oct 17 11:25:59.398335 DEB 4327  DBG:core:io_watch_add: [TCP_worker]
io_watch_add op (8 on 6) (0x83b1c0, 8, 19, 0x7f2da0d453c8,1), fd_no=2/1024
Oct 17 11:25:59.398344 DEB 4327  DBG:core:tcp_receive_timeout:
0x7f2da0d453c8 expired - (221, 222) lt=221
Oct 17 11:25:59.398352 DEB 4327  DBG:core:io_watch_del: [TCP_worker]
io_watch_del op on index -1 8 (0x83b1c0, 8, -1, 0x10,0x1) fd_no=3 called
Oct 17 11:25:59.398361 DEB 4327  DBG:core:tcpconn_release:  releasing con
0x7f2da0d453c8, state 0, fd=-1, id=1
Oct 17 11:25:59.398369 DEB 4327  DBG:core:tcpconn_release:  extra_data (nil)
Oct 17 11:25:59.398380 DEB 4335  DBG:core:handle_tcp_worker: reader
response= 7f2da0d453c8, 0 from 0
Oct 17 11:25:59.398406 DEB 4335  DBG:core:io_watch_add: [TCP_main]
io_watch_add op (48 on 6) (0x83b1c0, 48, 19, 0x7f2da0d453c8,1),
fd_no=35/1024
Oct 17 11:25:59.398423 DEB 4335  DBG:core:__tcpconn_lifetime: timeout for
hash=1 - 0x7f2da0d453c8 (223 > 221)
Oct 17 11:25:59.398429 DEB 4335  DBG:core:io_watch_del: [TCP_main]
io_watch_del op on index -1 48 (0x83b1c0, 48, -1, 0x10,0x3) fd_no=36 called

Best regards,
Dawid
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20161102/ed9c3bd8/attachment-0001.htm>

More information about the Users mailing list