[OpenSIPS-Users] TLS Connections Write Fail

Liviu Chircu liviu at opensips.org
Wed Jan 17 07:52:19 EST 2018 

Hi Royee,

Unfortunately, 2.1 is under the "unmaintained" status for well over a 
year now. I highly recommend considering an upgrade to 2.2.5 LTS - it 
has almost 2 absolute years worth of community usage and fixes, and we 
will roughly support it for almost another two. The differences are 
minimal [1], and there is a strong chance the bug will vanish.

Best regards,

[1]: http://www.opensips.org/Documentation/Migration-2-1-0-to-2-2-0

Liviu Chircu
OpenSIPS Developer
http://www.opensips-solutions.com

On 17.01.2018 11:01, Royee Tichauer via Users wrote:
> Hi everyone,
>
> Yesterday we experienced some bad behavior with opensips in a couple 
> of our production servers. What we saw is that all TLS/TCP connections 
> were closing and registrations were failing until we restarted 
> opensips. We can't understand why this happened. CPU metrics seem fine.
>
> We are using opensips 2.1.
>
> By looking at the logs we see a lot of errors which some of them 
> standout. Please let me know if any of these logs can say something 
> about the cause/trigger for the event.
>
> n 16 17:07:45 server 1 /usr/sbin/opensips[12990]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:07:45 server 1 /usr/sbin/opensips[12990]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 216
> Jan 16 17:07:45 server 1 /usr/sbin/opensips[13006]: 
> CRITICAL:core:io_watch_add: #012>>> [TCP_main] BUG trying to overwrite 
> entry 4670 in the hash(4670, 19, 0x7f333fbc07c8,1) with (4670, 19, 
> 0x7f3340282170,1)#012#012It seems you have hit a programming 
> bug.#012Please help us make OpenSIPS better by reporting it at 
> https://github.com/OpenSIPS/opensips/issues#012
> Jan 16 17:07:45 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:07:45 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 4671
> Jan 16 17:07:45 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (190)
>
>
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12995]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12995]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 94
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411776060 ms (now 411776160 ms), it may overlap..
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 400
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (135)
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411776160 ms (now 411776260 ms), it may overlap..
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:timer_ticker: timer task <tm-timer> already scheduled for 
> 411772300 ms (now 411776260 ms), it may overlap..
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 406
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (135)
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411776260 ms (now 411776360 ms), it may overlap..
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:core:tcp_connect_blocking: timeout 999977 ms elapsed from 1000000 s
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:proto_tls:proto_tls_send: connect failed
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:tm:msg_send: 
> send() for proto 3 failed
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: INFO:core:sig_usr: 
> signal 13 received
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:proto_tls:tls_write: TLS connection to <ip>:<port> write failed
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:proto_tls:tls_write: TLS write error:
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:proto_tls:tls_blocking_write: TLS failed to send data
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:proto_tls:proto_tls_send: failed to send
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> CRITICAL:core:send_all: send on -1 failed: Bad file descriptor
> Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: 
> ERROR:core:tcpconn_release: send_all failed
> gg
>
>
> an 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:core:tcp_connect_blocking: timeout 999197 ms elapsed from 1000000 s
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:proto_tls:proto_tls_send: connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:tm:msg_send: 
> send() for proto 3 failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 47
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411783490 ms (now 411783590 ms), it may overlap..
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1414
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (141)
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:core:tcp_connect_blocking: poll error: flags 28 - 4 8 16 32
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:core:tcp_connect_blocking: failed to retrieve SO_ERROR 
> [server=<ip>:<port>] (111) Connection refused
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> ERROR:proto_tls:proto_tls_send: connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:tm:msg_send: 
> send() for proto 3 failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 47
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: 
> ERROR:core:tcp_connect_blocking: timeout 999484 ms elapsed from 1000000 s
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: 
> ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: 
> ERROR:proto_tls:proto_tls_send: connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: ERROR:tm:msg_send: 
> send() for proto 3 failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 85
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411783590 ms (now 411783690 ms), it may overlap..
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411783690 ms (now 411783790 ms), it may overlap..
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1415
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (141)
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1419
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (141)
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1420
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: 
> INFO:core:send2child: no free tcp receiver, connection passed to the 
> least busy one (141)
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12957]: 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 411783790 ms (now 411783890 ms), it may overlap..
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12987]: 
> ERROR:core:tcp_connect_blocking: timeout 999053 ms elapsed from 1000000 s
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12987]: 
> ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
> Jan 16 17:11:46 server 1 /usr/sbin/opensips[12987]: 
> ERROR:proto_tls:proto_tls_send: connect failed
>
>
>
> _______________________________________________
> 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/20180117/402c2d90/attachment-0001.html>

More information about the Users mailing list