[OpenSIPS-Users] tcp io logs, loop
Răzvan Crainea
razvan at opensips.org
Thu Nov 3 09:11:09 CET 2016
Hi, Dawid!
Those are simply debug messages from the process's internal reactor.
There is nothing wrong with them, it simply proves the TCP interface
(for bin replication) is working properly. Unless there is no ERROR,
WARNING, CRITICAL logs, there is nothing to worry about.
Best regards,
Răzvan Crainea
OpenSIPS Solutions
www.opensips-solutions.com
On 11/02/2016 11:16 PM, Dawid Mielnik wrote:
> 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
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20161103/ab675c51/attachment-0001.htm>
More information about the Users
mailing list