BYE over TCP fails when TCP connection is broken

[danvirsen]

I recently got a report that the BYE signal in a B2BUA isn't sent to the other side at the end of a longer call (10+ minutes). It seems like the other side kills the TCP connection for some reason during the call.

The only hint I can see in the Drachtio log is the following, but I don't know if that means anything:

2024-10-23 13:53:20.603803 send 322 bytes to tcp/[1.1.1.1]:5060 at 13:53:20.603746:
BYE sip:[email protected]:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 2.2.2.2;branch=z9hG4bK80ja3ae591yrH
Max-Forwards: 70
From: "user 4" <sip:[email protected]>;tag=kecctqmt6t
To: <sip:[email protected]>;tag=b5a46e3e
Call-ID: 0795f56c-0bd6-123e-7bbc-0a4f836d1dc7
CSeq: 90287934 BYE
Content-Length: 0

2024-10-23 13:53:20.603815 nta.c:8519 outgoing_send() nta: sent BYE (90287934) to tcp/1.1.1.1:5060
2024-10-23 13:53:20.603824 SipDialogController::doSendRequestInsideDialog - created orq 0x5627602634a0 sending BYE to sip:[email protected]:5060;transport=tcp
2024-10-23 13:53:20.603833 tport.c:1181 tport_ref() tport_ref(0x56275fdef600): refcount is now 2
2024-10-23 13:53:20.603843 tport.c:1194 tport_unref() tport_unref(0x56275fdef600): refcount is now 1
2024-10-23 13:53:20.603851 RIP::RIP txnId: bf0aa033-6266-4c53-a873-a1ba8342200e dialogId 0795f56c-0bd6-123e-7bbc-0a4f836d1dc7;from-tag=kecctqmt6t clearDialogOnResponse true
2024-10-23 13:53:20.603858 SipDialogController::addRIP adding orq 0x5627602634a0
2024-10-23 13:53:20.603868 No connected clients found to handle incoming cdr:stop request
2024-10-23 13:53:20.603875 ClientController::removeApiRequest: clientMsgId 68796107-2912-41c4-943d-68758af1f44d; size: 0
2024-10-23 13:53:20.603928 Client::write_handler - wrote 516 bytes: system:0
2024-10-23 13:53:22.353459 tport.c:1181 tport_ref() tport_ref(0x56275fe04000): refcount is now 119
2024-10-23 13:53:22.353587 tport.c:1194 tport_unref() tport_unref(0x56275fe04000): refcount is now 118
2024-10-23 13:53:24.666193 tport.c:2985 tport_recv_event() tport_recv_event(0x56275fdef600): end of stream from tcp/1.1.1.1:5060 refcount is 1
2024-10-23 13:53:24.666250 tport.c:2212 tport_shutdown0() tport_shutdown0(0x56275fdef600, 2) tcp/1.1.1.1:5060
2024-10-23 13:53:24.666262 tport.c:2143 tport_close() tport_close(0x56275fdef600): tcp/1.1.1.1:5060

2024-10-23 13:53:24.666274 nta.c:8662 outgoing_tport_error() outgoing_tport_error: tport(0x56275fdef600) orq(0x5627602634a0) calling tport_release because we have pending 1
                                      ^ This

2024-10-23 13:53:24.666340 tport.c:2219 tport_shutdown0() tport_shutdown0(0x56275fdef600): after tport_close refcount is now 1
2024-10-23 13:53:24.666354 tport.c:2991 tport_recv_event() tport_recv_event(0x56275fdef600): back from tport_shutdown0 refcount is now 1
2024-10-23 13:53:26.693626 tport.c:1181 tport_ref() tport_ref(0x56275fe4a000): refcount is now 127
2024-10-23 13:53:26.693679 tport.c:1194 tport_unref() tport_unref(0x56275fe4a000): refcount is now 126

A more complete log can be found here:
hang_up_fails.txt

We are using Drachtio Server 0.8.26. Drachtio loglevel was set to debug, and Sofia was at 6.

Unfortunately I don't have a good way to reproduce this.
Please let me know if there is anything more I can do to help determine why we're having this issue.