Hi Razvan, I know they are debug level but because they only happen from time to time and they really flood the log I was worried this might be some loop error. Ok then, thank you for the info!
BR, Dawid On Thu, Nov 3, 2016 at 9:11 AM, Răzvan Crainea <[email protected]> wrote: > 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 Solutionswww.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:[email protected]} > 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 > [email protected]http://lists.opensips.org/cgi-bin/mailman/listinfo/users > > > > _______________________________________________ > Users mailing list > [email protected] > http://lists.opensips.org/cgi-bin/mailman/listinfo/users > >
_______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
