Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
wmasilva opened this issue Oct 22, 2024 · 0 comments
Open

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

wmasilva opened this issue Oct 22, 2024 · 0 comments
Labels
bug Something isn't working

Comments

@wmasilva
Copy link
Contributor

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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@wmasilva