<div dir="ltr">Hi everyone,<div><br></div><div>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.</div><div><br></div><div>We are using opensips 2.1.</div><div><br></div><div>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.</div><div><br></div><div><div>n 16 17:07:45 server 1 /usr/sbin/opensips[12990]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:07:45 server 1 /usr/sbin/opensips[12990]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 216</div><div><font color="#ff0000">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) </font>with (4670, 19, 0x7f3340282170,1)#012#012It seems you have hit a programming bug.#012Please help us make OpenSIPS better by reporting it at <a href="https://github.com/OpenSIPS/opensips/issues#012">https://github.com/OpenSIPS/opensips/issues#012</a></div><div>Jan 16 17:07:45 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:07:45 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 4671</div><div>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)</div><div><br></div><div><br></div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12995]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12995]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 94</div><div>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..</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 400</div><div>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)</div><div>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..</div><div>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..</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 406</div><div>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)</div><div>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..</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:core:tcp_connect_blocking: timeout 999977 ms elapsed from 1000000 s</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:proto_tls:proto_tls_send: connect failed</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:tm:msg_send: send() for proto 3 failed</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: INFO:core:sig_usr: signal 13 received</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:proto_tls:tls_write: TLS connection to <ip>:<port> write failed</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:proto_tls:tls_write: TLS write error:</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:proto_tls:tls_blocking_write: TLS failed to send data</div><div>Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:proto_tls:proto_tls_send: failed to send</div><div><font color="#ff0000">Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: CRITICAL:core:send_all: send on -1 failed: Bad file descriptor</font></div><div><font color="#ff0000">Jan 16 17:11:39 server 1 /usr/sbin/opensips[12960]: ERROR:core:tcpconn_release: send_all failed</font></div><div>gg</div><div><br></div><div><br></div><div>an 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:core:tcp_connect_blocking: timeout 999197 ms elapsed from 1000000 s</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:proto_tls:proto_tls_send: connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:tm:msg_send: send() for proto 3 failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 47</div><div>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..</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1414</div><div>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)</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:core:tcp_connect_blocking: poll error: flags 28 - 4 8 16 32 </div><div><font color="#ff0000">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</font></div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:proto_tls:proto_tls_send: connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: ERROR:tm:msg_send: send() for proto 3 failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12977]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 47</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: ERROR:core:tcp_connect_blocking: timeout 999484 ms elapsed from 1000000 s</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: ERROR:proto_tls:proto_tls_send: connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: ERROR:tm:msg_send: send() for proto 3 failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12997]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 85</div><div>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..</div><div>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..</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1415</div><div>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)</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1419</div><div>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)</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:probe_max_sock_buff: using snd buffer of 32768 kb</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[13006]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 1420</div><div>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)</div><div>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..</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12987]: ERROR:core:tcp_connect_blocking: timeout 999053 ms elapsed from 1000000 s</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12987]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed</div><div>Jan 16 17:11:46 server 1 /usr/sbin/opensips[12987]: ERROR:proto_tls:proto_tls_send: connect failed</div></div><div><br></div></div>