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.65k stars 1.44k forks source link

mod_sofia: no audio after 200 OK with different port in SDP from 183 Session in Progress #2630

Open wmasilva opened 1 month ago

wmasilva commented 1 month ago

Making a call to a remote side that sends RTP in sessions in progress but when it answers there is no audio. The problem is caused that it sends in the 200 OK SDP a different port number and crypto key, that SDP is not processed by FS.

I could reproduce the issue using sipp escenario with plain RTP and using the parameter: NOTE: with plain RTP FS can ajust to the correct port or IP using the rtp_auto_adjust parameter, but with SRTP is not possible since the key is diferent from the SIP/183 SDP.

I found old debates about this issue: https://forum.signalwire.community/t/freeswitch-ignores-sdp-in-200-ok-after-183/748 https://freeswitch-dev.freeswitch.narkive.com/LoQ0LunD/fs-doesn-t-update-rtp-port-when-sdp-changed-in-200ok-response-for-invite-message

knowing that is not a rfc behaviour (it should send a re-invite first i think), in the code it looks that is supported, in sofia.c, line:8501

        if (!switch_channel_test_flag(channel, CF_PROXY_MODE) && !switch_channel_test_flag(channel, CF_PROXY_MEDIA) &&
            r_sdp && (!is_dup_sdp || sofia_test_flag(tech_pvt, TFLAG_NEW_SDP)) && switch_core_media_ready(tech_pvt->session, SWITCH_MEDIA_TYPE_AUDIO) && !sofia_test_flag(tech_pvt, TFLAG_NOSDP_REINVITE)) {
            /* sdp changed since 18X w sdp, we're supposed to ignore it but we, of course, were pressured into supporting it */
            uint8_t match = 0;

            sofia_clear_flag(tech_pvt, TFLAG_NEW_SDP);
            switch_channel_set_flag(tech_pvt->channel, CF_REINVITE);

From the results, it looks taht this only applies to aleg and not to the remote side (bleg), after answer i see: 

2024-10-22 12:22:42.256892 97.97% [DEBUG] sofia.c:8519 Processing updated SDP
2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:8640 Audio params are unchanged for sofia/main/1000@default.com:5060.

It shows info only for channel 1000@default.com and not for the 00310@192.168.10.1:6070, the one that had changed SDP in the 200 OK. I'm using late negotiation, <param name="inbound-late-negotiation" value="true"/> i also tried without, but same result.

The dial string is:

<action application="bridge" data="{disable_rtp_auto_adjust=true}[^^:codec_string=PCMA][^^:absolute_codec_string=PCMA]sofia/main/sip:00310@192.168.10.1:6070"/>

Attach the sipp scenario to reproduce the issue. uas.xml.txt

Full call log: 

2024-10-22 12:22:27.957170 99.00% [NOTICE] switch_channel.c:1142 New Channel sofia/main/1000@default.com:5060 [493929e9-8273-44d4-a8da-cb89856b0627]
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_NEW (Cur 1 Tot 10)
2024-10-22 12:22:27.957170 99.00% [INFO] sofia.c:10460 sofia/main/1000@default.com:5060 receiving invite from 192.168.10.196:5099 version: 1.10.13-dev git 97cb672 2024-10-15 14:06:59Z 64bit call-id: 4_869476828@192.168.10.196
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ PCMU 0
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ PCMA 8
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ telephone-event 101
2024-10-22 12:22:27.957170 99.00% [DEBUG] sofia.c:10554 verifying acl "domains" for ip/port 192.168.10.196:0.
2024-10-22 12:22:27.957170 99.00% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [received][100]
2024-10-22 12:22:27.957170 99.00% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=- 20024 20024 IN IP4 192.168.10.196
s=SDP data
c=IN IP4 192.168.10.196
t=0 0
m=audio 12072 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2024-10-22 12:22:27.957170 99.00% [DEBUG] sofia.c:7906 (sofia/main/1000@default.com:5060) State Change CS_NEW -> CS_INIT
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:600 (sofia/main/1000@default.com:5060) State NEW
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_INIT (Cur 1 Tot 10)
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:624 (sofia/main/1000@default.com:5060) State INIT
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_state_machine.c:624 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:97 sofia/main/1000@default.com:5060 SOFIA INIT
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:40 sofia/main/1000@default.com:5060 Standard INIT
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:48 (sofia/main/1000@default.com:5060) State Change CS_INIT -> CS_ROUTING
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:624 (sofia/main/1000@default.com:5060) State INIT going to sleep
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_ROUTING (Cur 1 Tot 10)
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_channel.c:2399 (sofia/main/1000@default.com:5060) Callstate Change DOWN -> RINGING
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:640 (sofia/main/1000@default.com:5060) State ROUTING
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_state_machine.c:640 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:158 sofia/main/1000@default.com:5060 SOFIA ROUTING
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:230 sofia/main/1000@default.com:5060 Standard ROUTING
2024-10-22 12:22:27.957170 99.00% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->20 in context default
Dialplan: sofia/main/1000@default.com:5060 parsing [default->trunk-sipp] continue=false
Dialplan: sofia/main/1000@default.com:5060 Regex (FAIL) [trunk-sipp] ${sip_network_ip}(192.168.10.196) =~ /^192.168.10.186$/ break=on-false
Dialplan: sofia/main/1000@default.com:5060 parsing [default->check_acl] continue=true
Dialplan: sofia/main/1000@default.com:5060 Regex (PASS) [check_acl] ${acl(${network_addr} domains)}(true) =~ /^true$/ break=on-false
Dialplan: sofia/main/1000@default.com:5060 Action set(process_cdr=false) 
Dialplan: sofia/main/1000@default.com:5060 parsing [default->check_auth] continue=true
Dialplan: sofia/main/1000@default.com:5060 Regex (FAIL) [check_auth] ${sip_authorized}() =~ /^true$/ break=never
Dialplan: sofia/main/1000@default.com:5060 ANTI-Action respond(407) 
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:281 (sofia/main/1000@default.com:5060) State Change CS_ROUTING -> CS_EXECUTE
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:640 (sofia/main/1000@default.com:5060) State ROUTING going to sleep
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_EXECUTE (Cur 1 Tot 10)
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:647 (sofia/main/1000@default.com:5060) State EXECUTE
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_state_machine.c:647 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:213 sofia/main/1000@default.com:5060 SOFIA EXECUTE
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:323 sofia/main/1000@default.com:5060 Standard EXECUTE
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_session.c:2735 sofia/main/1000@default.com:5060 Send KeyFrame
EXECUTE [depth=0] sofia/main/1000@default.com:5060 set(process_cdr=false)
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_session.c:2967 sofia/main/1000@default.com:5060 receive message [APPLICATION_EXEC]
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_dptools.c:1671 SET sofia/main/1000@default.com:5060 [process_cdr]=[false]
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_session.c:2983 sofia/main/1000@default.com:5060 receive message [APPLICATION_EXEC_COMPLETE]
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_session.c:2735 sofia/main/1000@default.com:5060 Send KeyFrame
EXECUTE [depth=0] sofia/main/1000@default.com:5060 respond(407)
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_session.c:2967 sofia/main/1000@default.com:5060 receive message [APPLICATION_EXEC]
2024-10-22 12:22:27.957170 99.00% [ALERT] mod_dptools.c:1585 sofia/main/1000@default.com:5060 receive message [RESPOND]
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:2358 Responding with 407 [(null)]
2024-10-22 12:22:27.957170 99.00% [NOTICE] mod_sofia.c:2426 Hangup sofia/main/1000@default.com:5060 [CS_EXECUTE] [CALL_REJECTED]
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_session.c:2983 sofia/main/1000@default.com:5060 receive message [APPLICATION_EXEC_COMPLETE]
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_session.c:2983 sofia/main/1000@default.com:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:647 (sofia/main/1000@default.com:5060) State EXECUTE going to sleep
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_HANGUP (Cur 1 Tot 10)
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:844 (sofia/main/1000@default.com:5060) Callstate Change RINGING -> HANGUP
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:846 (sofia/main/1000@default.com:5060) State HANGUP
2024-10-22 12:22:27.957170 99.00% [ALERT] switch_core_state_machine.c:846 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:469 Channel sofia/main/1000@default.com:5060 hanging up, cause: CALL_REJECTED
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:576 Challenging call
2024-10-22 12:22:27.957170 99.00% [DEBUG] mod_sofia.c:614 Responding to INVITE with: 407
2024-10-22 12:22:27.957170 99.00% [DEBUG] switch_core_state_machine.c:59 sofia/main/1000@default.com:5060 Standard HANGUP, cause: CALL_REJECTED
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:846 (sofia/main/1000@default.com:5060) State HANGUP going to sleep
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:616 (sofia/main/1000@default.com:5060) State Change CS_HANGUP -> CS_REPORTING
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_REPORTING (Cur 1 Tot 10)
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:932 (sofia/main/1000@default.com:5060) State REPORTING
2024-10-22 12:22:27.979359 99.00% [ALERT] switch_core_state_machine.c:932 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:168 sofia/main/1000@default.com:5060 Standard REPORTING, cause: CALL_REJECTED
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:932 (sofia/main/1000@default.com:5060) State REPORTING going to sleep
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:607 (sofia/main/1000@default.com:5060) State Change CS_REPORTING -> CS_DESTROY
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_session.c:1748 Session 10 (sofia/main/1000@default.com:5060) Locked, Waiting on external entities
2024-10-22 12:22:27.979359 99.00% [NOTICE] switch_core_session.c:1766 Session 10 (sofia/main/1000@default.com:5060) Ended
2024-10-22 12:22:27.979359 99.00% [NOTICE] switch_core_session.c:1770 Close Channel sofia/main/1000@default.com:5060 [CS_DESTROY]
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:735 (sofia/main/1000@default.com:5060) Running State Change CS_DESTROY (Cur 0 Tot 10)
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:745 (sofia/main/1000@default.com:5060) State DESTROY
2024-10-22 12:22:27.979359 99.00% [ALERT] switch_core_state_machine.c:745 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:27.979359 99.00% [DEBUG] mod_sofia.c:380 sofia/main/1000@default.com:5060 SOFIA DESTROY
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:175 sofia/main/1000@default.com:5060 Standard DESTROY
2024-10-22 12:22:27.979359 99.00% [DEBUG] switch_core_state_machine.c:745 (sofia/main/1000@default.com:5060) State DESTROY going to sleep
2024-10-22 12:22:28.016240 99.00% [NOTICE] switch_channel.c:1142 New Channel sofia/main/1000@default.com:5060 [f287840a-9d0c-4751-933d-d14b508c8230]
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_NEW (Cur 1 Tot 11)
2024-10-22 12:22:28.016240 99.00% [INFO] sofia.c:10460 sofia/main/1000@default.com:5060 receiving invite from 192.168.10.196:5099 version: 1.10.13-dev git 97cb672 2024-10-15 14:06:59Z 64bit call-id: 4_869476828@192.168.10.196
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ PCMU 0
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ PCMA 8
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ telephone-event 101
2024-10-22 12:22:28.016240 99.00% [DEBUG] sofia.c:10554 verifying acl "domains" for ip/port 192.168.10.196:0.
2024-10-22 12:22:28.016240 99.00% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [received][100]
2024-10-22 12:22:28.016240 99.00% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=- 20024 20024 IN IP4 192.168.10.196
s=SDP data
c=IN IP4 192.168.10.196
t=0 0
m=audio 12072 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2024-10-22 12:22:28.016240 99.00% [DEBUG] sofia.c:7906 (sofia/main/1000@default.com:5060) State Change CS_NEW -> CS_INIT
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:600 (sofia/main/1000@default.com:5060) State NEW
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_INIT (Cur 1 Tot 11)
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:624 (sofia/main/1000@default.com:5060) State INIT
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:624 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_sofia.c:97 sofia/main/1000@default.com:5060 SOFIA INIT
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:40 sofia/main/1000@default.com:5060 Standard INIT
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:48 (sofia/main/1000@default.com:5060) State Change CS_INIT -> CS_ROUTING
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:624 (sofia/main/1000@default.com:5060) State INIT going to sleep
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_ROUTING (Cur 1 Tot 11)
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_channel.c:2399 (sofia/main/1000@default.com:5060) Callstate Change DOWN -> RINGING
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:640 (sofia/main/1000@default.com:5060) State ROUTING
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:640 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_sofia.c:158 sofia/main/1000@default.com:5060 SOFIA ROUTING
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:230 sofia/main/1000@default.com:5060 Standard ROUTING
2024-10-22 12:22:28.016240 99.00% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->20 in context local
Dialplan: sofia/main/1000@default.com:5060 parsing [local->200ok] continue=false
Dialplan: sofia/main/1000@default.com:5060 Regex (PASS) [200ok] destination_number(20) =~ /^20$/ break=on-false
Dialplan: sofia/main/1000@default.com:5060 Action bridge({disable_rtp_auto_adjust=true}[^^:codec_string=PCMA][^^:absolute_codec_string=PCMA]sofia/main/sip:00310@192.168.10.1:6070) 
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:281 (sofia/main/1000@default.com:5060) State Change CS_ROUTING -> CS_EXECUTE
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:640 (sofia/main/1000@default.com:5060) State ROUTING going to sleep
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_EXECUTE (Cur 1 Tot 11)
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:647 (sofia/main/1000@default.com:5060) State EXECUTE
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:647 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_sofia.c:213 sofia/main/1000@default.com:5060 SOFIA EXECUTE
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:323 sofia/main/1000@default.com:5060 Standard EXECUTE
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_session.c:2735 sofia/main/1000@default.com:5060 Send KeyFrame
EXECUTE [depth=0] sofia/main/1000@default.com:5060 bridge({disable_rtp_auto_adjust=true}[^^:codec_string=PCMA][^^:absolute_codec_string=PCMA]sofia/main/sip:00310@192.168.10.1:6070)
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_session.c:2967 sofia/main/1000@default.com:5060 receive message [APPLICATION_EXEC]
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_event.c:1737 Parsing variable [disable_rtp_auto_adjust]=[true]
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_ivr_originate.c:2863 Parsing session specific variables
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_event.c:1737 Parsing variable [codec_string]=[PCMA]
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_event.c:1737 Parsing variable [absolute_codec_string]=[PCMA]
2024-10-22 12:22:28.016240 99.00% [NOTICE] switch_channel.c:1142 New Channel sofia/main/00310@192.168.10.1:6070 [ed9a30a8-e35c-4512-a442-62e872eceb90]
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_sofia.c:5121 (sofia/main/00310@192.168.10.1:6070) State Change CS_NEW -> CS_INIT
2024-10-22 12:22:28.016240 99.00% [INFO] switch_cpp.cpp:1466 limit.lua: inbound limit for account:1000@default.com [total]: 4
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_limit.c:124 incr called: total_account:1000@default.com max:4, interval:0
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_hash.c:193 Usage for total_account:1000@default.com is now 1/4
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_INIT (Cur 2 Tot 12)
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:624 (sofia/main/00310@192.168.10.1:6070) State INIT
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:624 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_sofia.c:97 sofia/main/00310@192.168.10.1:6070 SOFIA INIT
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_media.c:821 ADD PMAP REQ PCMA 8
2024-10-22 12:22:28.016240 99.00% [INFO] sofia_glue.c:1659 sofia/main/00310@192.168.10.1:6070 sending invite call-id: (null)
2024-10-22 12:22:28.016240 99.00% [DEBUG] sofia_glue.c:1662 sofia/main/00310@192.168.10.1:6070 sending invite version: 1.10.13-dev git 97cb672 2024-10-15 14:06:59Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1729582186 1729582187 IN IP4 192.168.10.182
s=FreeSWITCH
c=IN IP4 192.168.10.182
t=0 0
m=audio 10362 RTP/AVP 8 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:40 sofia/main/00310@192.168.10.1:6070 Standard INIT
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:48 (sofia/main/00310@192.168.10.1:6070) State Change CS_INIT -> CS_ROUTING
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:624 (sofia/main/00310@192.168.10.1:6070) State INIT going to sleep
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_ROUTING (Cur 2 Tot 12)
2024-10-22 12:22:28.016240 99.00% [DEBUG] sofia.c:7493 Channel sofia/main/00310@192.168.10.1:6070 entering state [calling][0]
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:640 (sofia/main/00310@192.168.10.1:6070) State ROUTING
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:640 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:28.016240 99.00% [DEBUG] mod_sofia.c:158 sofia/main/00310@192.168.10.1:6070 SOFIA ROUTING
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_ivr_originate.c:67 (sofia/main/00310@192.168.10.1:6070) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:640 (sofia/main/00310@192.168.10.1:6070) State ROUTING going to sleep
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 12)
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:659 (sofia/main/00310@192.168.10.1:6070) State CONSUME_MEDIA
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:659 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:28.016240 99.00% [DEBUG] switch_core_state_machine.c:659 (sofia/main/00310@192.168.10.1:6070) State CONSUME_MEDIA going to sleep
2024-10-22 12:22:28.016240 99.00% [ALERT] switch_core_state_machine.c:698 sofia/main/00310@192.168.10.1:6070 session thread sleep state: CS_CONSUME_MEDIA!
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_core_state_machine.c:702 sofia/main/00310@192.168.10.1:6070 session thread wake state: CS_CONSUME_MEDIA!
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_core_media.c:821 ADD PMAP RES PCMA 8
2024-10-22 12:22:28.056171 99.00% [ALERT] sofia.c:1343 sofia/main/00310@192.168.10.1:6070 Same Callee ID "Outbound Call" <00310>
2024-10-22 12:22:28.056171 99.00% [DEBUG] sofia.c:7493 Channel sofia/main/00310@192.168.10.1:6070 entering state [proceeding][183]
2024-10-22 12:22:28.056171 99.00% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=user1 53655765 2353687637 IN IP4 192.168.10.1
s=-
c=IN IP4 192.168.10.1
t=0 0
m=audio 6000 RTP/AVP 8
a=rtpmap:8 PCMA/8000

2024-10-22 12:22:28.056171 99.00% [NOTICE] sofia.c:7506 Pre-Answer sofia/main/00310@192.168.10.1:6070!
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_channel.c:3585 (sofia/main/00310@192.168.10.1:6070) Callstate Change DOWN -> EARLY
2024-10-22 12:22:28.056171 99.00% [ALERT] sofia.c:7506 sofia/main/00310@192.168.10.1:6070 receive message [PROGRESS_EVENT]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5524 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5586 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:3730 Set Codec sofia/main/00310@192.168.10.1:6070 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_codec.c:132 sofia/main/00310@192.168.10.1:6070 Original read codec set to PCMA:8
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5861 No 2833 in SDP.  Disable 2833 dtmf and switch to INFO
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/main/00310@192.168.10.1:6070] 192.168.10.182 port 10362 -> 192.168.10.1 port 6000 codec: 8 ms: 20
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_rtp.c:4566 Starting timer [soft] 160 bytes per 20ms
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:9001 sofia/main/00310@192.168.10.1:6070 Set rtp dtmf delay to 40
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_core_state_machine.c:698 sofia/main/00310@192.168.10.1:6070 session thread sleep state: CS_CONSUME_MEDIA!
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_originate.c:3862 sofia/main/1000@default.com:5060 receive message [PROGRESS]
2024-10-22 12:22:28.056171 99.00% [INFO] switch_ivr_originate.c:3862 Sending early media
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5524 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5586 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5524 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5436 Set telephone-event payload to 101@8000
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:3730 Set Codec sofia/main/1000@default.com:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_codec.c:132 sofia/main/1000@default.com:5060 Original read codec set to PCMU:0
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5796 Set telephone-event payload to 101@8000
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:5854 sofia/main/1000@default.com:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/main/1000@default.com:5060] 192.168.10.182 port 10958 -> 192.168.10.196 port 12072 codec: 0 ms: 20
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_rtp.c:4566 Starting timer [soft] 160 bytes per 20ms
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:8971 sofia/main/1000@default.com:5060 Set 2833 dtmf send payload to 101
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:8978 sofia/main/1000@default.com:5060 Set 2833 dtmf receive payload to 101
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:9001 sofia/main/1000@default.com:5060 Set rtp dtmf delay to 40
2024-10-22 12:22:28.056171 99.00% [NOTICE] sofia_media.c:90 Pre-Answer sofia/main/1000@default.com:5060!
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_channel.c:3585 (sofia/main/1000@default.com:5060) Callstate Change RINGING -> EARLY
2024-10-22 12:22:28.056171 99.00% [ALERT] sofia_media.c:90 sofia/main/1000@default.com:5060 receive message [PROGRESS_EVENT]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_media.c:8640 Audio params are unchanged for sofia/main/1000@default.com:5060.
2024-10-22 12:22:28.056171 99.00% [DEBUG] mod_sofia.c:2617 Ring SDP:
v=0
o=FreeSWITCH 1729581590 1729581591 IN IP4 192.168.10.182
s=FreeSWITCH
c=IN IP4 192.168.10.182
t=0 0
m=audio 10958 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

2024-10-22 12:22:28.056171 99.00% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [early][183]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [sofia/main/00310@192.168.10.1:6070] Peer UUID: ed9a30a8-e35c-4512-a442-62e872eceb90
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_originate.c:4249 sofia/main/1000@default.com:5060 receive message [AUDIO_SYNC]
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_originate.c:4246 sofia/main/00310@192.168.10.1:6070 receive message [AUDIO_SYNC]
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_bridge.c:1646 sofia/main/00310@192.168.10.1:6070 receive message [AUDIO_SYNC]
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr.c:217 sofia/main/1000@default.com:5060 receive message [AUDIO_SYNC]
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_bridge.c:1645 sofia/main/1000@default.com:5060 receive message [AUDIO_SYNC]
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_bridge.c:1747 sofia/main/00310@192.168.10.1:6070 receive message [BRIDGE]
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_ivr_bridge.c:1755 sofia/main/1000@default.com:5060 receive message [BRIDGE]
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_ivr_bridge.c:1791 (sofia/main/00310@192.168.10.1:6070) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_core_state_machine.c:702 sofia/main/00310@192.168.10.1:6070 session thread wake state: CS_CONSUME_MEDIA!
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_state_machine.c:581 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 12)
2024-10-22 12:22:28.056171 99.00% [DEBUG] switch_core_state_machine.c:650 (sofia/main/00310@192.168.10.1:6070) State EXCHANGE_MEDIA
2024-10-22 12:22:28.056171 99.00% [ALERT] switch_core_state_machine.c:650 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:28.056171 99.00% [DEBUG] mod_sofia.c:672 SOFIA EXCHANGE_MEDIA
2024-10-22 12:22:28.116314 99.00% [ALERT] switch_core_media.c:15949 sofia/main/1000@default.com:5060 receive message [TRANSCODING_NECESSARY]
2024-10-22 12:22:28.196188 99.00% [DEBUG] switch_rtp.c:7698 Correct audio ip/port confirmed.
2024-10-22 12:22:28.196188 99.00% [ALERT] switch_core_media.c:15949 sofia/main/00310@192.168.10.1:6070 receive message [TRANSCODING_NECESSARY]
freeswitch@debian> 
freeswitch@debian> 
freeswitch@debian> 
freeswitch@debian> 
2024-10-22 12:22:38.076956 98.23% [ALERT] sofia.c:1343 sofia/main/00310@192.168.10.1:6070 Same Callee ID "Outbound Call" <00310>
2024-10-22 12:22:38.076956 98.23% [DEBUG] sofia.c:7493 Channel sofia/main/00310@192.168.10.1:6070 entering state [proceeding][180]
2024-10-22 12:22:38.076956 98.23% [NOTICE] sofia.c:7604 Ring-Ready sofia/main/00310@192.168.10.1:6070!
2024-10-22 12:22:38.076956 98.23% [DEBUG] switch_channel.c:3513 (sofia/main/00310@192.168.10.1:6070) Callstate Change EARLY -> RINGING
2024-10-22 12:22:38.076956 98.23% [ALERT] sofia.c:7604 sofia/main/00310@192.168.10.1:6070 receive message [RING_EVENT]
freeswitch@debian> 
2024-10-22 12:22:42.076425 97.97% [ALERT] sofia.c:1343 sofia/main/00310@192.168.10.1:6070 Same Callee ID "Outbound Call" <00310>
2024-10-22 12:22:42.076425 97.97% [DEBUG] sofia.c:7493 Channel sofia/main/00310@192.168.10.1:6070 entering state [completing][200]
2024-10-22 12:22:42.076425 97.97% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=user1 53655765 2353687637 IN IP4 192.168.10.1
s=-
c=IN IP4 192.168.10.1
t=0 0
m=audio 6002 RTP/AVP 8

2024-10-22 12:22:42.076425 97.97% [DEBUG] sofia.c:7493 Channel sofia/main/00310@192.168.10.1:6070 entering state [ready][200]
2024-10-22 12:22:42.076425 97.97% [NOTICE] sofia.c:8623 Channel [sofia/main/00310@192.168.10.1:6070] has been answered
2024-10-22 12:22:42.076425 97.97% [DEBUG] switch_channel.c:3912 (sofia/main/00310@192.168.10.1:6070) Callstate Change RINGING -> ACTIVE
2024-10-22 12:22:42.076425 97.97% [ALERT] sofia.c:8623 sofia/main/00310@192.168.10.1:6070 receive message [ANSWER_EVENT]
2024-10-22 12:22:42.076425 97.97% [ALERT] switch_ivr_bridge.c:730 sofia/main/1000@default.com:5060 receive message [ANSWER]
2024-10-22 12:22:42.076425 97.97% [DEBUG] switch_core_media.c:8640 Audio params are unchanged for sofia/main/1000@default.com:5060.
2024-10-22 12:22:42.076425 97.97% [DEBUG] mod_sofia.c:914 Local SDP sofia/main/1000@default.com:5060:
v=0
o=FreeSWITCH 1729581590 1729581592 IN IP4 192.168.10.182
s=FreeSWITCH
c=IN IP4 192.168.10.182
t=0 0
m=audio 10958 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

2024-10-22 12:22:42.076425 97.97% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [completed][200]
2024-10-22 12:22:42.076425 97.97% [NOTICE] switch_ivr_bridge.c:730 Channel [sofia/main/1000@default.com:5060] has been answered
2024-10-22 12:22:42.076425 97.97% [DEBUG] switch_channel.c:3912 (sofia/main/1000@default.com:5060) Callstate Change EARLY -> ACTIVE
2024-10-22 12:22:42.076425 97.97% [ALERT] switch_ivr_bridge.c:730 sofia/main/1000@default.com:5060 receive message [ANSWER_EVENT]
2024-10-22 12:22:42.096765 97.97% [DEBUG] switch_rtp.c:7698 Correct audio ip/port confirmed.
2024-10-22 12:22:42.137066 97.97% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [ready][200]
2024-10-22 12:22:42.157039 97.97% [ALERT] switch_ivr_bridge.c:326 sofia/main/00310@192.168.10.1:6070 receive message [DISPLAY]
2024-10-22 12:22:42.157039 97.97% [ALERT] switch_ivr_bridge.c:326 sofia/main/1000@default.com:5060 receive message [DISPLAY]
2024-10-22 12:22:42.157039 97.97% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [calling][0]
2024-10-22 12:22:42.256892 97.97% [DEBUG] sofia.c:7493 Channel sofia/main/1000@default.com:5060 entering state [ready][200]
2024-10-22 12:22:42.256892 97.97% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=- 20024 20025 IN IP4 192.168.10.196
s=SDP data
c=IN IP4 192.168.10.196
t=0 0
m=audio 12072 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:5524 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:5586 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:5436 Set telephone-event payload to 101@8000
2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:5796 Set telephone-event payload to 101@8000
2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:5854 sofia/main/1000@default.com:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2024-10-22 12:22:42.256892 97.97% [DEBUG] sofia.c:8519 Processing updated SDP
2024-10-22 12:22:42.256892 97.97% [DEBUG] switch_core_media.c:8640 Audio params are unchanged for sofia/main/1000@default.com:5060.
2024-10-22 12:22:44.136171 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.156545 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.156545 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.156545 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.176221 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.196395 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.196395 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.196395 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.216517 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.236397 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.236397 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.236397 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.256170 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.276665 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.276665 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.276665 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.296184 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.316198 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.316198 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.316198 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.336457 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.356505 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.356505 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.356505 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.376661 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.396914 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.396914 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.396914 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.396914 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.436519 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.436519 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.436519 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.457134 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.457134 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.457134 97.83% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.457134 97.83% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.496198 97.77% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.516236 97.77% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.516236 97.77% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.516236 97.77% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.536572 97.77% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.556878 97.77% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.556878 97.77% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.556878 97.77% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 3 consecutive flaws, adding 3 flaw penalty
2024-10-22 12:22:44.556878 97.77% [NOTICE] sofia.c:1065 Hangup sofia/main/1000@default.com:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2024-10-22 12:22:44.556878 97.77% [DEBUG] mod_hash.c:293 Usage for total_account:1000@default.com is now 0
2024-10-22 12:22:44.556878 97.77% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/main/1000@default.com:5060]
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_rtp.c:7843 sofia/main/00310@192.168.10.1:6070 audio timeout
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/main/00310@192.168.10.1:6070]
2024-10-22 12:22:44.576890 97.77% [NOTICE] switch_ivr_bridge.c:1027 Hangup sofia/main/00310@192.168.10.1:6070 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:650 (sofia/main/00310@192.168.10.1:6070) State EXCHANGE_MEDIA going to sleep
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:581 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_HANGUP (Cur 2 Tot 12)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:844 (sofia/main/00310@192.168.10.1:6070) Callstate Change ACTIVE -> HANGUP
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:846 (sofia/main/00310@192.168.10.1:6070) State HANGUP
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_state_machine.c:846 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:44.576890 97.77% [DEBUG] mod_sofia.c:463 sofia/main/00310@192.168.10.1:6070 Overriding SIP cause 480 with 200 from the other leg
2024-10-22 12:22:44.576890 97.77% [DEBUG] mod_sofia.c:469 Channel sofia/main/00310@192.168.10.1:6070 hanging up, cause: NORMAL_CLEARING
2024-10-22 12:22:44.576890 97.77% [DEBUG] mod_sofia.c:523 Sending BYE to sofia/main/00310@192.168.10.1:6070
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:59 sofia/main/00310@192.168.10.1:6070 Standard HANGUP, cause: NORMAL_CLEARING
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:846 (sofia/main/00310@192.168.10.1:6070) State HANGUP going to sleep
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_rtp.c:1588 sofia/main/00310@192.168.10.1:6070 audio 2 consecutive flaws, adding 2 flaw penalty
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:616 (sofia/main/00310@192.168.10.1:6070) State Change CS_HANGUP -> CS_REPORTING
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:581 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_REPORTING (Cur 2 Tot 12)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:932 (sofia/main/00310@192.168.10.1:6070) State REPORTING
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_state_machine.c:932 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:168 sofia/main/00310@192.168.10.1:6070 Standard REPORTING, cause: NORMAL_CLEARING
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:932 (sofia/main/00310@192.168.10.1:6070) State REPORTING going to sleep
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:607 (sofia/main/00310@192.168.10.1:6070) State Change CS_REPORTING -> CS_DESTROY
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_session.c:1748 Session 12 (sofia/main/00310@192.168.10.1:6070) Locked, Waiting on external entities
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_ivr_bridge.c:1893 sofia/main/1000@default.com:5060 receive message [UNBRIDGE]
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_ivr_bridge.c:1893 sofia/main/1000@default.com:5060 skip receive message [UNBRIDGE] (channel is hungup already)
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_session.c:2983 sofia/main/1000@default.com:5060 receive message [APPLICATION_EXEC_COMPLETE]
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_session.c:2983 sofia/main/1000@default.com:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:647 (sofia/main/1000@default.com:5060) State EXECUTE going to sleep
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_HANGUP (Cur 2 Tot 12)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:844 (sofia/main/1000@default.com:5060) Callstate Change ACTIVE -> HANGUP
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:846 (sofia/main/1000@default.com:5060) State HANGUP
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_state_machine.c:846 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:44.576890 97.77% [DEBUG] mod_sofia.c:469 Channel sofia/main/1000@default.com:5060 hanging up, cause: NORMAL_CLEARING
2024-10-22 12:22:44.576890 97.77% [NOTICE] switch_core_session.c:1766 Session 12 (sofia/main/00310@192.168.10.1:6070) Ended
2024-10-22 12:22:44.576890 97.77% [NOTICE] switch_core_session.c:1770 Close Channel sofia/main/00310@192.168.10.1:6070 [CS_DESTROY]
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:735 (sofia/main/00310@192.168.10.1:6070) Running State Change CS_DESTROY (Cur 1 Tot 12)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:745 (sofia/main/00310@192.168.10.1:6070) State DESTROY
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_state_machine.c:745 sofia/main/00310@192.168.10.1:6070 Send KeyFrame
2024-10-22 12:22:44.576890 97.77% [DEBUG] mod_sofia.c:380 sofia/main/00310@192.168.10.1:6070 SOFIA DESTROY
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:175 sofia/main/00310@192.168.10.1:6070 Standard DESTROY
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:745 (sofia/main/00310@192.168.10.1:6070) State DESTROY going to sleep
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:59 sofia/main/1000@default.com:5060 Standard HANGUP, cause: NORMAL_CLEARING
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:846 (sofia/main/1000@default.com:5060) State HANGUP going to sleep
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:616 (sofia/main/1000@default.com:5060) State Change CS_HANGUP -> CS_REPORTING
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:581 (sofia/main/1000@default.com:5060) Running State Change CS_REPORTING (Cur 1 Tot 12)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:932 (sofia/main/1000@default.com:5060) State REPORTING
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_state_machine.c:932 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:168 sofia/main/1000@default.com:5060 Standard REPORTING, cause: NORMAL_CLEARING
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:932 (sofia/main/1000@default.com:5060) State REPORTING going to sleep
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:607 (sofia/main/1000@default.com:5060) State Change CS_REPORTING -> CS_DESTROY
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_session.c:1748 Session 11 (sofia/main/1000@default.com:5060) Locked, Waiting on external entities
2024-10-22 12:22:44.576890 97.77% [NOTICE] switch_core_session.c:1766 Session 11 (sofia/main/1000@default.com:5060) Ended
2024-10-22 12:22:44.576890 97.77% [NOTICE] switch_core_session.c:1770 Close Channel sofia/main/1000@default.com:5060 [CS_DESTROY]
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:735 (sofia/main/1000@default.com:5060) Running State Change CS_DESTROY (Cur 0 Tot 12)
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:745 (sofia/main/1000@default.com:5060) State DESTROY
2024-10-22 12:22:44.576890 97.77% [ALERT] switch_core_state_machine.c:745 sofia/main/1000@default.com:5060 Send KeyFrame
2024-10-22 12:22:44.576890 97.77% [DEBUG] mod_sofia.c:380 sofia/main/1000@default.com:5060 SOFIA DESTROY
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:175 sofia/main/1000@default.com:5060 Standard DESTROY
2024-10-22 12:22:44.576890 97.77% [DEBUG] switch_core_state_machine.c:745 (sofia/main/1000@default.com:5060) State DESTROY going to sleep
freeswitch@debian>
sagarmalam commented 1 day ago

@wmasilva Did you find any solution to this problem ? I am also facing same issue Thanks