search

signalwire / freeswitch

FreeSWITCH is a Software Defined Telecom Stack enabling the digital transformation from proprietary telecom switches to a versatile software implementation that runs on any commodity hardware. From a Raspberry PI to a multi-core server, FreeSWITCH can unlock the telecommunications potential of any device.
https://freeswitch.com/#getting-started
Other
3.51k stars 1.41k forks source link

mod_sofia is processing the SIP BYE with delay of 5 seconds for a bridge call scenario #1268

Open adil-mafzool opened 3 years ago

adil-mafzool commented 3 years ago

Describe the bug mod_sofia processing SIP BYE with delay of 5 seconds

To Reproduce

  1. Using this example configuration dialplan with sip call received by freeswitch on IP: 10.211.195.221 with call to be bridged to IP: 10.211.195.222

  2. Dial from IP source: 10.211.195.221

  3. Hangup the call from SIP endpoint from the caller IP source: 10.211.195.221

  4. FreeSWITCH doesnt hangup the call with first SIP bye rather it does it after 5 seconds

Expected behavior mod_sofia is processing the SIP BYE with delay of 5 seconds for a bridge call scenario. SIP endpoint side re-transmits four times using SIP timer before FreeSwitch hangup the call. It is seeing that receiving first SIP bye message sofia call back function is called: sofia_event_callback which calls line:2661 switch_core_session_queue_signal_data(session, de) to signal data the BYE to process it. But the process dispatch event function at line: 2266 sofia_process_dispatch_event is called after 5 seconds.

Please find the details of SIP call for call-id: 257715-210712150136-53185991@0ad3c3dd andCSeq: 461679504 BYE attached logs: (https://github.com/signalwire/freeswitch/files/6825016/console.log) and (https://github.com/signalwire/freeswitch/files/6825017/freeswitch.log)

Package version or git hash

Trace logs console.log freeswitch.log Find the freeswitch.log and console.log attached

backtrace from core file N-A

andywolk commented 3 years ago

According to the log you are not on the latest sofia-sip. And you are not on e7d7720.

nua.c:1168 nua_handle_unref_user() nua: nua_handle_unref_user: entering
nua.c:1173 nua_handle_unref_user() nua: nua_r_handle_unref with invalid handle 0x7f7d6801b7b0

That messaging was removed at some point: https://github.com/freeswitch/sofia-sip/commit/8071e8accd250bd1d7758dd16166382b48a6e6d4#diff-6aedd628831e54417177ef5474202f506f706549e64e799a981434e69aa6ddadL1173

So..... Please rebuild the latest sofia and rebuild freeswitch and try again.

andywolk commented 3 years ago

Please post fresh logs once you are up to date.

adil-mafzool commented 3 years ago

@andywolk Have managed to repeat the test with sofia-sip (e7d7720 v1.13.4) and FreeSWITCH Version 1.10.7-dev+git~20210624T220752Z~33040f2a43~64bit (git 33040f2 2021-06-24 22:07:52Z 64bit) with same results: -

Please find the details of SIP call for call-id: 2-210716092727-1600709798@0ad3c3dd and CSeq: 1597353384 BYE attached logs: console.log freeswitch.log

adil-mafzool commented 3 years ago

It looks like that that default poll_sec is set to 5 seconds with as switch_core_session_read_frame is using ioflag SWITCH_IO_FLAG_NONE. https://github.com/signalwire/freeswitch/blob/4c049140037a6dd401ea3fb7240118eedfce3e5f/src/switch_rtp.c#L7247 https://github.com/signalwire/freeswitch/blob/4c049140037a6dd401ea3fb7240118eedfce3e5f/src/switch_rtp.c#L7416

https://github.com/signalwire/freeswitch/blob/4c049140037a6dd401ea3fb7240118eedfce3e5f/src/switch_rtp.c#L7439

This meant that when SIP BYE is processed as the sofia channel is stuck for 5 seconds.

It would make sense to enable SWITCH_IO_FLAG_NOBLOCK for switch_core_session_read_frame function calls in switch_ivr_bridge.c and switch_ivr_originate.c files or reduce to the time in milliseconds. Will do a pull request to reduce the timeout to 200ms as this would need no change of logic since change in switch_ivr_bridge.c and switch_ivr_originate.c files may break other scenarios.

greenbea commented 3 years ago

I have the same behavior on 1.10.3 when using proxy_media, FreeSWITCH responds to the BYE only after 5 seconds, but I don't if it's related to this issue.

elkpi commented 2 years ago

you maybe set rtp_notimer_during_bridge=true, bridge need rtp readable are used to trigger.

peiffer1 commented 1 year ago

Hi , I have a similar issu with bridge application: I use a the bridge application in a LUA script: ... session:execute("bridge",dialString) ...

In the freeswitch log I see that when leg-A hangup, leg-B hangup 5s later:

Freeswitch receive well the BYE from leg-A: BYE sip:CCQ_999011000003_32394@10.10.13.199:5080;transport=udp SIP/2.0 Record-Route: sip:35.234.91.59:5060;r2=on;lr=on;ftag=5903D5D7-64A43205000B3DAE-B848B700;ngcplb=yes Record-Route: sip:127.0.0.1;r2=on;lr=on;ftag=5903D5D7-64A43205000B3DAE-B848B700;ngcplb=yes Record-Route: sip:127.0.0.1:5062;lr=on;ftag=5903D5D7-64A43205000B3DAE-B848B700;rtpprx=yes;evmona=yes;evmonb=yes Via: SIP/2.0/UDP 10.10.13.196:5080;branch=z9hG4bK86ba.bd1fd201.0 Via: SIP/2.0/UDP 35.234.91.59:5060;branch=z9hG4bK86ba.29bf56a509a486f0f9325bfc7b03770e.0 Via: SIP/2.0/UDP 127.0.0.1:5062;rport=5062;branch=z9hG4bK86ba.95a506a961435e0801a7fc18f998e4ff.0 Via: SIP/2.0/UDP 127.0.0.1:5080;received=127.0.0.1;branch=z9hG4bKZSBEaaPX;rport=5080 From: "C1U4FN C1U4LN" sip:999013000003323241@965.demo-rainbow-voice.eu1.sip.openrainbow.com;tag=5903D5D7-64A43205000B3DAE-B848B700 To: sip:CCQ_999011000003_32394@965.demo-rainbow-voice.eu1.sip.openrainbow.com;tag=9aS30aH18Ka4D CSeq: 2798 BYE Call-ID: 370DFD79E7F42C1CF557E3A9187B5369_pbx-1 Route: sip:10.10.13.196:5080;lr;fi=sip:10.10.13.199:5080 Max-Forwards: 67 Accept: application/conference-info+xml,application/csta+xml,application/dialog-info+xml,application/sdp,application/service-user-profile+xml,application/simple-message-summary,application/x-as-feature-event+xml,application/xml,message/sipfrag,multipart/mixed,multipart/related Allow: ACK, BYE, CANCEL, INVITE, MESSAGE, NOTIFY, OPTIONS, PRACK, REFER, SUBSCRIBE, UPDATE Supported: 100rel, answermode, eventlist, join, replaces, sdp-anat, tdialog P-Asserted-Identity: "C1U4FN C1U4LN" sip:32324@965.demo-rainbow-voice.eu1.sip.openrainbow.com Content-Length: 0

Bridge application leave the session of leg-A ([sofia/external/999013000003323241@965.demo-rainbow-voice.eu1.sip.openrainbow.com), but take about 4-5 seconds for leaving the leg-B ([sofia/external/AAM000002) e0e8aec5-7f32-4a7b-96b3-ff827b777847 2023-07-04 16:52:16.485357 99.30% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/external/999013000003323241@965.demo-rainbow-voice.eu1.sip.openrainbow.com] eef60ce8-4439-4a97-b221-38a66ef8a6df 2023-07-04 16:52:20.785358 99.43% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/external/AAM000002]

AFter that the BYE is sent to leg-B

Regards, Eric

adil-mafzool commented 1 month ago

you maybe set rtp_notimer_during_bridge=true, bridge need rtp readable are used to trigger.

The variable was set when the issue were seen