freeswitch icon indicating copy to clipboard operation
freeswitch copied to clipboard

Published 20 hours ago • verified publisher icon signalwire

BYE not forwarded to A side of the call

Open zenichev opened this issue 11 months ago • 1 comments

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:[email protected]: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:[email protected]>;tag=4914B847-65E98EB1000A1144-FC6F96C0
To: <sip:[email protected]>;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/[email protected] [CS_HIBERNATE] [NORMAL_CLEARING]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_ivr_bridge.c:1334 sofia/internal/[email protected] 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/[email protected]) 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/[email protected]) Callstate Change DOWN -> HANGUP
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/[email protected]) 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:[email protected]>;tag=4914B847-65E98EB1000A1144-FC6F96C0
To: <sip:[email protected]>;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/[email protected] hanging up, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_ivr_bridge.c:1470 (sofia/internal/[email protected]) State Change CS_HIBERNATE -> CS_EXECUTE
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:59 sofia/internal/[email protected] Standard HANGUP, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/[email protected]) 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/[email protected]) State EXECUTE
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:213 sofia/internal/[email protected] SOFIA EXECUTE
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:323 sofia/internal/[email protected] Standard EXECUTE
2024-03-07 10:55:14.532181 32.47% [NOTICE] switch_core_state_machine.c:341 Hangup sofia/internal/[email protected] [CS_EXECUTE] [NORMAL_CLEARING]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/[email protected]) State EXECUTE going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/[email protected]) 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/[email protected] 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/[email protected] 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/[email protected]) Callstate Change ACTIVE -> HANGUP
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/[email protected]) State HANGUP
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:462 sofia/internal/[email protected] 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/[email protected] hanging up, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/internal/[email protected]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:59 sofia/internal/[email protected] Standard HANGUP, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/[email protected]) State HANGUP going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/[email protected]) State Change CS_HANGUP -> CS_REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/[email protected]) 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/[email protected]) State REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/[email protected]) State HANGUP going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/[email protected]) State Change CS_HANGUP -> CS_REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/[email protected]) 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/[email protected]) State REPORTING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:168 sofia/internal/[email protected] Standard REPORTING, cause: NORMAL_CLEARING
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/[email protected]) State REPORTING going to sleep
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/[email protected]) 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/[email protected]) Locked, Waiting on external entities
2024-03-07 10:55:14.532181 32.47% [NOTICE] switch_core_session.c:1761 Session 2 (sofia/internal/[email protected]) Ended
2024-03-07 10:55:14.532181 32.47% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal/[email protected] [CS_DESTROY]
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/[email protected]) 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/[email protected]) State DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] mod_sofia.c:379 sofia/internal/[email protected] SOFIA DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:175 sofia/internal/[email protected] Standard DESTROY
2024-03-07 10:55:14.532181 32.47% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/[email protected]) State DESTROY going to sleep
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:168 sofia/internal/[email protected] Standard REPORTING, cause: NORMAL_CLEARING
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/[email protected]) State REPORTING going to sleep
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/[email protected]) 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/[email protected]) Locked, Waiting on external entities
2024-03-07 10:55:14.552812 32.47% [NOTICE] switch_core_session.c:1761 Session 1 (sofia/internal/[email protected]) Ended
2024-03-07 10:55:14.552812 32.47% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal/[email protected] [CS_DESTROY]
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/[email protected]) 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/[email protected]) State DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] mod_sofia.c:379 sofia/internal/[email protected] SOFIA DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:175 sofia/internal/[email protected] Standard DESTROY
2024-03-07 10:55:14.552812 32.47% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/[email protected]) 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 avatar Mar 07 '24 13:03 zenichev

I think this can be related to:

  • this : https://github.com/signalwire/freeswitch/issues/960
  • and this : https://github.com/signalwire/freeswitch/pull/1256

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

zenichev avatar Mar 07 '24 13:03 zenichev