[OpenSIPS-Users] tcp io logs, loop

Dawid Mielnik dawid.mielnik at gmail.com
Thu Nov 3 09:24:20 CET 2016 

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 <razvan at opensips.org> 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: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 listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
>
> _______________________________________________
> 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/bdb25480/attachment-0001.htm>

More information about the Users mailing list