BYE not forwarded to A side of the call

[zenichev]

Describe the bug
BYE request is not forwarded to the A side of the call, after fsctl crash + fsctl recover.

I've implemented the HA setup following this freeswitch guide:
https://developer.signalwire.com/freeswitch/FreeSWITCH-Explained/Configuration/High-Availability/

It works fine in terms of:

• sessions get recovered successfully, I see channels in the list after recovering
• media is handled correctly

But the in-dialog signaling works only half way.
What I mean is, that when B side of the call sends BYE,
freeswitch indeed terminates all the existing channels correctly, those related to this SIP call (sip channels list is empty after that), but for some reason it doesn't forward BYE further to the A side.

Interesting fact, it works fine, if I send BYE from the A side of the call.
The bridge_early_media is set to false.

To Reproduce
Steps to reproduce the behavior:

1. Use this guide to setup HA: https://developer.signalwire.com/freeswitch/FreeSWITCH-Explained/Configuration/High-Availability/
2. Create two subscribers
3. Setup a call A to B
4. Emulate a freeswitch crash with fsctl crash
5. Start the freeswitch manually or wait till the systemd restarts it, and recover SIP channels with fsctl recover
6. Send BYE from the B side of the call

Expected behavior
BYE is forwarded to the A side of the call.

Package version or git hash

• release v1.10.9

Trace logs

recv 588 bytes from udp/[127.0.0.1]:5062 at 10:55:14.534618:
------------------------------------------------------------------------
BYE sip:nobody@127.0.0.1:5085 SIP/2.0
Record-Route: <sip:127.0.0.1:5062;lr=on;ftag=Dg8BBtBUc2BDr;vsf=dEpMcnd3alJnclh3RnpjQ0NkaGR0Skxyd3dqUmdy;evmona=yes;evmonb=yes>
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK2cf3.ef7ecd229f86d32e91989e8a26cb534a.0
Via: SIP/2.0/UDP 127.0.0.1:5080;received=127.0.0.1;branch=z9hG4bKmml73aZx;rport=5080
From: <sip:1003@sip.domain.com>;tag=4914B847-65E98EB1000A1144-FC6F96C0
To: <sip:testuser1001@sip.domain.com>;tag=Dg8BBtBUc2BDr
CSeq: 1052 BYE
Call-ID: 72affa5c-570b-123d-cb98-08002747ce00
Max-Forwards: 69
Content-Length: 0


2024-03-07 10:55:14.532181 32.47% [NOTICE] sofia.c:1065 Hangup sofia/internal/1003@sip.domain.com [CS_HIBERNATE] [NORMAL_CLEARING]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_ivr_bridge.c:1334 sofia/internal/1003@sip.domain.com skip receive message [UNBRIDGE] (channel is hungup already)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@sip.domain.com) Running State Change CS_HANGUP (Cur 2 Tot 2)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/1003@sip.domain.com) Callstate Change DOWN -> HANGUP
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1003@sip.domain.com) State HANGUP
send 579 bytes to udp/[127.0.0.1]:5062 at 10:55:14.544813:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK2cf3.ef7ecd229f86d32e91989e8a26cb534a.0
Via: SIP/2.0/UDP 127.0.0.1:5080;received=127.0.0.1;branch=z9hG4bKmml73aZx;rport=5080
From: <sip:1003@sip.domain.com>;tag=4914B847-65E98EB1000A1144-FC6F96C0
To: <sip:testuser1001@sip.domain.com>;tag=Dg8BBtBUc2BDr
Call-ID: 72affa5c-570b-123d-cb98-08002747ce00
CSeq: 1052 BYE
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0


2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:468 Channel sofia/internal/1003@sip.domain.com hanging up, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_ivr_bridge.c:1470 (sofia/internal/testuser1001@sip.domain.com) State Change CS_HIBERNATE -> CS_EXECUTE
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:59 sofia/internal/1003@sip.domain.com Standard HANGUP, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/testuser1001@sip.domain.com) Running State Change CS_EXECUTE (Cur 2 Tot 2)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/testuser1001@sip.domain.com) State EXECUTE
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:213 sofia/internal/testuser1001@sip.domain.com SOFIA EXECUTE
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:323 sofia/internal/testuser1001@sip.domain.com Standard EXECUTE
2024-03-07 10:55:14.532181 32.47% [NOTICE] switch_core_state_machine.c:341 Hangup sofia/internal/testuser1001@sip.domain.com [CS_EXECUTE] [NORMAL_CLEARING]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/testuser1001@sip.domain.com) State EXECUTE going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/testuser1001@sip.domain.com) Running State Change CS_HANGUP (Cur 2 Tot 2)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:337 sofia/internal/testuser1001@sip.domain.com skip receive message [VIDEO_SYNC] (channel is hungup already)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:338 sofia/internal/testuser1001@sip.domain.com skip receive message [REQUEST_IMAGE_MEDIA] (channel is hungup already)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/testuser1001@sip.domain.com) Callstate Change ACTIVE -> HANGUP
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/testuser1001@sip.domain.com) State HANGUP
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:462 sofia/internal/testuser1001@sip.domain.com Overriding SIP cause 480 with 200 from the other leg
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:468 Channel sofia/internal/testuser1001@sip.domain.com hanging up, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/internal/testuser1001@sip.domain.com
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:59 sofia/internal/testuser1001@sip.domain.com Standard HANGUP, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/testuser1001@sip.domain.com) State HANGUP going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/testuser1001@sip.domain.com) State Change CS_HANGUP -> CS_REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/testuser1001@sip.domain.com) Running State Change CS_REPORTING (Cur 2 Tot 2)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/testuser1001@sip.domain.com) State REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1003@sip.domain.com) State HANGUP going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/1003@sip.domain.com) State Change CS_HANGUP -> CS_REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@sip.domain.com) Running State Change CS_REPORTING (Cur 2 Tot 2)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1003@sip.domain.com) State REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:168 sofia/internal/1003@sip.domain.com Standard REPORTING, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1003@sip.domain.com) State REPORTING going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/1003@sip.domain.com) State Change CS_REPORTING -> CS_DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_session.c:1743 Session 2 (sofia/internal/1003@sip.domain.com) Locked, Waiting on external entities
2024-03-07 10:55:14.532181 32.47% [NOTICE] switch_core_session.c:1761 Session 2 (sofia/internal/1003@sip.domain.com) Ended
2024-03-07 10:55:14.532181 32.47% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal/1003@sip.domain.com [CS_DESTROY]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1003@sip.domain.com) Running State Change CS_DESTROY (Cur 1 Tot 2)
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1003@sip.domain.com) State DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:379 sofia/internal/1003@sip.domain.com SOFIA DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:175 sofia/internal/1003@sip.domain.com Standard DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1003@sip.domain.com) State DESTROY going to sleep
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:168 sofia/internal/testuser1001@sip.domain.com Standard REPORTING, cause: NORMAL_CLEARING
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/testuser1001@sip.domain.com) State REPORTING going to sleep
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/testuser1001@sip.domain.com) State Change CS_REPORTING -> CS_DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_session.c:1743 Session 1 (sofia/internal/testuser1001@sip.domain.com) Locked, Waiting on external entities
2024-03-07 10:55:14.552812 32.47% [NOTICE] switch_core_session.c:1761 Session 1 (sofia/internal/testuser1001@sip.domain.com) Ended
2024-03-07 10:55:14.552812 32.47% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal/testuser1001@sip.domain.com [CS_DESTROY]
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/testuser1001@sip.domain.com) Running State Change CS_DESTROY (Cur 0 Tot 2)
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/testuser1001@sip.domain.com) State DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] mod_sofia.c:379 sofia/internal/testuser1001@sip.domain.com SOFIA DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:175 sofia/internal/testuser1001@sip.domain.com Standard DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/testuser1001@sip.domain.com) State DESTROY going to sleep

other things noticed
I've noticed that if I don't emulate the crash of the freeswitch, and I hang up the call from the B side (which works correctly in this case), there is a tiny difference in the log, in the working case it doesn't have this log row at the end:

State DESTROY going to sleep

[zenichev]

I think this can be related to:

• this : outbound Calls (leg b) are not getting cleared, even after call gets hang-up  #960
• and this : [Core] Fix bridge_early_media #1256

Even though the mentioned above PL is in our version, but it doesn't fix the problem.