[BUG] File descriptor leak when TLS connection fails to establish.

[GouthamPMadhava]

OpenSIPS version you are running

[root@Neil-E1-Z1-ACCM sip_messages]# opensips -V
version: opensips 3.4.14 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 277554f
main.c compiled on 11:20:24 Aug 28 2025 with gcc 4.8.5
[root@Neil-E1-Z1-ACCM sip_messages]#

Describe the bug

We use OpenSIPs in our soft switch where it front faces our application server (AS) and every SIP message goes out and comes in through OpenSIPs. The communication between our AS and OpenSIPs is always UDP and from OpenSIPs to other end point could be UDP, TCP or TLS. Our application uses OPTIONS to ping the endpoint to keep track of it's availability. The frequency of OPTIONS is thrice in 10secs.

We experienced a file descriptor leak with OpenSIPs 3.4.9 when the OPTIONS goes over TLS and fails to establish for any reason. Noticed an issue is fixed through #3634 and we upgraded OpenSIPs to 3.4.14 (like shown above). However, we continue to see the leak even with 3.4.14 and we did confirm the flow of TLS connection handling is indeed hitting the fixes provided through #3634, but still we see leak. Looks like we are hitting some other condition as the logs show the following error:

CRITICAL:core:handle_io: >>> read_fd:no fd read for conn 0x7f026c675fa0, rw 2

It seems you have hit a programming bug.
Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues

To Reproduce

Send OPTIONS to a valid IP and a port over TLS but misconfigure to fail the TLS connection. In our case, we end up having 'Unknow CA' error.

Expected behavior

The socket/file descriptor must be cleared out when TLS connection fails to establish.

Relevant System Logs

[root@Neil-E1-Z1-ACCM opensips]# cat /home/xyzzy/opensips.log.new
2025-08-28T15:01:22.425-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_msg_opt: SIP Request:
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_msg_opt:  method:  <OPTIONS>
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_msg_opt:  uri:     <sip:172.29.108.20:5062;transport=tls>
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_msg_opt:  version: <SIP/2.0>
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=ffffffffffffffff
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:_parse_to: end of header reached, state=10
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:_parse_to: display={}, ruri={sip:172.29.108.20:5062;transport=tls}
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:172.29.108.20:5062;transport=tls]
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:get_hdr_field: to body [<sip:172.29.108.20:5062;transport=tls>
]
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKi.u14187748211A.r86685.gs6141>; state=16
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_via: end of header reached, state=5
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: via found, flags=ffffffffffffffff
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: this is the first via
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <OPTIONS>
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:get_hdr_field: content_length=0
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:get_hdr_field: found end of header
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:receive_msg: After parse_msg...
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:receive_msg: preparing to run routing scripts...
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:maxfwd:is_maxfwd_present: value = 70
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:sipmsgops:has_totag: no totag
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=200
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:rr:is_preloaded: Yes
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:grep_sock_info_ext: checking if host==us: 14==14 &&  [10.204.193.182] == [10.204.193.182]
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:grep_sock_info_ext: checking if port 5066 matches port 5066
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:rr:after_loose: Topmost route URI: 'sip:10.204.193.182:5066;lr' is me
2025-08-28T15:01:22.426-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=200
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:get_hdr_field: found end of header
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:rr:find_next_route: No next Route HF found
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:rr:after_loose: No next URI found!
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:grep_sock_info_ext: checking if host==us: 13==14 &&  [172.29.108.20] == [10.204.193.182]
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:grep_sock_info_ext: checking if host==us: 13==14 &&  [172.29.108.20] == [10.204.193.182]
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:grep_sock_info_ext: checking if host==us: 13==14 &&  [172.29.108.20] == [10.204.193.182]
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:check_self: host != me
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=ffffffffffffffff
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKi.u14187748211A.r86685.gs6141>; state=16
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_via: end of header reached, state=5
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_to_param: tag=a!172%29%108%20+5062!.gs6141.glt1756407679.r86685
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_to_param: end of header reached, state=11
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:_parse_to: end of header reached, state=29
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:_parse_to: display={}, ruri={sip:10.204.193.182:54586}
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:comp_scriptvar: str 20: 172.29.108.20
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:comp_scriptvar: str 29: 10.204.193.182
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:mk_proxy: doing DNS lookup...
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:MD5StringArray: MD5 calculated: f0d54024bf632b51a81512a8ca1b2971
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=60
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=2000
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:parse_headers: flags=ffffffffffffffff
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:forward_request: sending:
OPTIONS sip:172.29.108.20:5062;transport=tls SIP/2.0
Record-Route: <sip:10.204.193.182:5061;transport=tls;r2=on;lr>
Record-Route: <sip:10.204.193.182:5066;r2=on;lr>
To: <sip:172.29.108.20:5062;transport=tls>
Via: SIP/2.0/TLS 10.204.193.182:5061;branch=z9hG4bK501f.f0d54024bf632b51a81512a8ca1b2971.0
Via: SIP/2.0/UDP 10.204.193.182:54586;branch=z9hG4bKi.u14187748211A.r86685.gs6141
Call-ID: hb@172.29.108.20.gs6141.s2350.mi2309.lt1756407677.ct1756407682.d5.4.i5.TR.0.MEQerr
From: <sip:10.204.193.182:54586>;tag=a!172%29%108%20+5062!.gs6141.glt1756407679.r86685
Max-Forwards: 69
CSeq: 1 OPTIONS
Content-Length: 0

.
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:forward_request: orig. len=455, new_len=624, proto=3
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:tcp_conn_get: con found in state 0
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:tcp_conn_get: tcp connection found (0x7f026c8f2378), acquiring fd
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:tcp_conn_get: c= 0x7f026c8f2378, n=16, Usock=67
2025-08-28T15:01:22.427-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172104]: DBG:core:handle_worker: read response= 7f026c8f2378, 1, fd -1 from 4 (172095)
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:tcp_conn_get: after receive_fd: c= 0x7f026c8f2378 n=8 fd=4
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:proto_tls:proto_tls_send: sending via fd 4...
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:proto_tls:proto_tls_send: after write: c=0x7f026c8f2378 n=0 fd=4
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:proto_tls:proto_tls_send: buf=
OPTIONS sip:172.29.108.20:5062;transport=tls SIP/2.0
Record-Route: <sip:10.204.193.182:5061;transport=tls;r2=on;lr>
Record-Route: <sip:10.204.193.182:5066;r2=on;lr>
To: <sip:172.29.108.20:5062;transport=tls>
Via: SIP/2.0/TLS 10.204.193.182:5061;branch=z9hG4bK501f.f0d54024bf632b51a81512a8ca1b2971.0
Via: SIP/2.0/UDP 10.204.193.182:54586;branch=z9hG4bKi.u14187748211A.r86685.gs6141
Call-ID: hb@172.29.108.20.gs6141.s2350.mi2309.lt1756407677.ct1756407682.d5.4.i5.TR.0.MEQerr
From: <sip:10.204.193.182:54586>;tag=a!172%29%108%20+5062!.gs6141.glt1756407679.r86685
Max-Forwards: 69
CSeq: 1 OPTIONS
Content-Length: 0
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:tcpconn_release:  releasing con 0x7f026c8f2378, state 5, fd=-1, id=1483858000
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:tcpconn_release:  extra_data 0x7f026c8f2780
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:destroy_avp_list: destroying list (nil)
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172095]: DBG:core:receive_msg: cleaning up
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172104]: DBG:core:handle_worker: read response= 7f026c8f2378, 5, fd -1 from 4 (172095)
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172104]: DBG:core:io_watch_add: [TCP_main] io_watch_add op (151 on 4) (0xa60660, 151, 19, 0x7f026c8f2378,2), fd_no=17/1024
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172104]: DBG:core:handle_tcpconn_ev: connection 0x7f026c8f2378 fd 151 is now writable
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172104]: DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 2 151 (0xa60660, 151, 2, 0x0,0x2) fd_no=18 called
2025-08-28T15:01:22.428-04:00 [local2] [debug] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172104]: DBG:core:send2worker: to tcp worker 0 (172098/6) load 0, 0x7f026c8f2378/151 rw 2
2025-08-28T15:01:22.428-04:00 [local2] [crit] Neil-E1-Z1-ACCM /usr/sbin/opensipsExternal[172098]: CRITICAL:core:handle_io:
>>> read_fd:no fd read for conn 0x7f026c8f2378, rw 2

It seems you have hit a programming bug.
Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues
[root@Neil-E1-Z1-ACCM opensips]#

OS/environment information

• Operating System:
  [xyzzy@Neil-E1-Z1-ACCM ~]$ cat /etc/redhat-release
  Red Hat Enterprise Linux release 8.10 (Ootpa)
  [xyzzy@Neil-E1-Z1-ACCM ~]$

• OpenSIPS installation:
  We download the OpenSIPs from https://download.opensips.org/, compile it, build an RPM of our own and install the RPM on our application server.

• other relevant information:

Additional context

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[leokoutikas]

The issue is 100% easily reproducible and leads to an exhaustion of file descriptors which makes OpenSIPS inoperable. Please let us know if more information is needed or if we can help in any way.

[bogdan-iancu]

The posted logs seems to be the side-effect of the fd leaking, and not related to the leaking itself. Could you detail on the scenario generating the fd leak ?

[leokoutikas]

Very simply, setup a destination SIP endpoint with a certificate that is not trusted by OpenSIPs. Continue trying to send SIP messages to this destination. TLS setup will fail as expected but FDs are being leaked. Monitor each opensips process for FDs in use and you should see one or more child processes show continued climbing of FDs. Once limit is reached, that specific process will not process anything anymore until restarted.

[bogdan-iancu]

OK, that is strange as #3634 , commit 19bc7d0 should fix exactly this kind of issue. I will try to reproduce what you mentioned

[GouthamPMadhava]

Yes, like I mentioned in my original post, we did try later version which has fixes for #3634, confirmed it's hitting the code that is fixed and yet we continue to see the leak.