Hey folks, I’m having an issue and not really sure how to troubleshoot from here. I have the following extension in my default context for local extensions:
<extension name="local-extension">
<condition field="destination_number" expression="^(100[0-9])$">
<action application="export" data="dialed_extension=$1"/>
<action application="set" data="call_timeout=30"/>
<action application="set" data="hangup_after_bridge=true"/>
<action application="set" data="continue_on_fail=true"/>
<action application="bridge" data="user/${dialed_extension}@${domain_name}"/>
<action application="answer"/>
<action application="sleep" data="1000"/>
<action application="bridge" data="loopback/app=voicemail:default ${domain_name} ${dialed_extension}"/>
</condition>
</extension>
For calls between extensions, this is working as intended (rings the other extension, sends to voicemail if there is no answer). I’m currently working on setting up inbound calling from the PSTN via 2 SIP trunking providers, which connect to a different SIP profile. I have the following extension in my public context to handle the DID:
<extension name="did">
<condition field="destination_number" expression="^<did number>$">
<action application="set" data="domain_name=<domain name>"/>
<action application="transfer" data="1001 XML default"/>
</condition>
</extension>
This rings the extension as expected, and if the user answers, two way audio is established correctly. However if the user doesn’t answer, sending to voicemail is not working. The log shows the following:
2023-03-19 09:44:04.358646 99.70% [NOTICE] switch_channel.c:1123 New Channel sofia/external/<calling number>@185.8.92.11 [17b17e25-20c6-4fea-b6b0-8ab635a71424]
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_NEW (Cur 1 Tot 3)
2023-03-19 09:44:04.358646 99.70% [INFO] sofia.c:10453 sofia/external/<calling number>@185.8.92.11 receiving invite from 185.8.92.11:5060 version: 1.10.9 -release-21-a615e85afc 64bit call-id: 4631e66b4ec0de3540317e5967a07d87@185.8.92.11:5060
2023-03-19 09:44:04.358646 99.70% [DEBUG] sofia.c:10547 verifying acl "sip-providers" for ip/port 185.8.92.11:0.
2023-03-19 09:44:04.358646 99.70% [DEBUG] sofia.c:7487 Channel sofia/external/<calling number>@185.8.92.11 entering state [received][100]
2023-03-19 09:44:04.358646 99.70% [DEBUG] sofia.c:7497 Remote SDP:
v=0
o=root 222422740 222422740 IN IP4 185.8.92.11
s=SureVoIP Core 2.0
c=IN IP4 185.8.92.11
t=0 0
m=audio 17162 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2023-03-19 09:44:04.358646 99.70% [DEBUG] sofia.c:7900 (sofia/external/<calling number>@185.8.92.11) State Change CS_NEW -> CS_INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:600 (sofia/external/<calling number>@185.8.92.11) State NEW
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_INIT (Cur 1 Tot 3)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:624 (sofia/external/<calling number>@185.8.92.11) State INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:97 sofia/external/<calling number>@185.8.92.11 SOFIA INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:40 sofia/external/<calling number>@185.8.92.11 Standard INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:48 (sofia/external/<calling number>@185.8.92.11) State Change CS_INIT -> CS_ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:624 (sofia/external/<calling number>@185.8.92.11) State INIT going to sleep
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_ROUTING (Cur 1 Tot 3)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_channel.c:2380 (sofia/external/<calling number>@185.8.92.11) Callstate Change DOWN -> RINGING
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/external/<calling number>@185.8.92.11) State ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:158 sofia/external/<calling number>@185.8.92.11 SOFIA ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:230 sofia/external/<calling number>@185.8.92.11 Standard ROUTING
2023-03-19 09:44:04.358646 99.70% [INFO] mod_dialplan_xml.c:639 Processing <calling number> <<calling number>>-><called number> in context public
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [public->public_extensions] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [public_extensions] destination_number(<called number>) =~ /^(100[0-9])$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [public->egglab_did] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [egglab_did] destination_number(<called number>) =~ /^<another number>$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [public->james_did] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (PASS) [james_did] destination_number(<called number>) =~ /^(?:\+)?<called number>$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 Action set(domain_name=<domain name>)
Dialplan: sofia/external/<calling number>@185.8.92.11 Action transfer(1001 XML default)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:281 (sofia/external/<calling number>@185.8.92.11) State Change CS_ROUTING -> CS_EXECUTE
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/external/<calling number>@185.8.92.11) State ROUTING going to sleep
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_EXECUTE (Cur 1 Tot 3)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:647 (sofia/external/<calling number>@185.8.92.11) State EXECUTE
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:213 sofia/external/<calling number>@185.8.92.11 SOFIA EXECUTE
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:323 sofia/external/<calling number>@185.8.92.11 Standard EXECUTE
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 set(domain_name=<domain name>)
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_dptools.c:1673 SET sofia/external/<calling number>@185.8.92.11 [domain_name]=[<domain name>]
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 transfer(1001 XML default)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_ivr.c:2288 (sofia/external/<calling number>@185.8.92.11) State Change CS_EXECUTE -> CS_ROUTING
2023-03-19 09:44:04.358646 99.70% [NOTICE] switch_ivr.c:2295 Transfer sofia/external/<calling number>@185.8.92.11 to XML[1001@default]
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:647 (sofia/external/<calling number>@185.8.92.11) State EXECUTE going to sleep
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_ROUTING (Cur 1 Tot 3)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/external/<calling number>@185.8.92.11) State ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:149 Call appears to be already acknowledged
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:158 sofia/external/<calling number>@185.8.92.11 SOFIA ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:230 sofia/external/<calling number>@185.8.92.11 Standard ROUTING
2023-03-19 09:44:04.358646 99.70% [INFO] mod_dialplan_xml.c:639 Processing <calling number> <<calling number>>->1001 in context default
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [default->line-test-delayed-echo-test] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [line-test-delayed-echo-test] destination_number(1001) =~ /^17074$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [default->line-test-echo-test] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [line-test-echo-test] destination_number(1001) =~ /^17073$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [default->line-test-quiet-line] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [line-test-quiet-line] destination_number(1001) =~ /^17072$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [default->line-test-ringback] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [line-test-ringback] destination_number(1001) =~ /^17071$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [default->voicemail] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (FAIL) [voicemail] destination_number(1001) =~ /^vmain$|^1571$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 parsing [default->local-extension] continue=false
Dialplan: sofia/external/<calling number>@185.8.92.11 Regex (PASS) [local-extension] destination_number(1001) =~ /^(100[0-9])$/ break=on-false
Dialplan: sofia/external/<calling number>@185.8.92.11 Action export(dialed_extension=1001)
Dialplan: sofia/external/<calling number>@185.8.92.11 Action set(call_timeout=30)
Dialplan: sofia/external/<calling number>@185.8.92.11 Action set(hangup_after_bridge=true)
Dialplan: sofia/external/<calling number>@185.8.92.11 Action set(continue_on_fail=true)
Dialplan: sofia/external/<calling number>@185.8.92.11 Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/external/<calling number>@185.8.92.11 Action answer()
Dialplan: sofia/external/<calling number>@185.8.92.11 Action sleep(1000)
Dialplan: sofia/external/<calling number>@185.8.92.11 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:281 (sofia/external/<calling number>@185.8.92.11) State Change CS_ROUTING -> CS_EXECUTE
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/external/<calling number>@185.8.92.11) State ROUTING going to sleep
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_EXECUTE (Cur 1 Tot 3)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:647 (sofia/external/<calling number>@185.8.92.11) State EXECUTE
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:213 sofia/external/<calling number>@185.8.92.11 SOFIA EXECUTE
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:323 sofia/external/<calling number>@185.8.92.11 Standard EXECUTE
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 export(dialed_extension=1001)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [dialed_extension]=[1001]
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 set(call_timeout=30)
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_dptools.c:1673 SET sofia/external/<calling number>@185.8.92.11 [call_timeout]=[30]
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 set(hangup_after_bridge=true)
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_dptools.c:1673 SET sofia/external/<calling number>@185.8.92.11 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 set(continue_on_fail=true)
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_dptools.c:1673 SET sofia/external/<calling number>@185.8.92.11 [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 bridge(user/1001@<domain name>)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_channel.c:1269 sofia/external/<calling number>@185.8.92.11 EXPORTING[export_vars] [dialed_extension]=[1001] to event
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_ivr_originate.c:2291 Parsing global variables
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_channel.c:1269 sofia/external/<calling number>@185.8.92.11 EXPORTING[export_vars] [dialed_extension]=[1001] to event
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_ivr_originate.c:2291 Parsing global variables
2023-03-19 09:44:04.358646 99.70% [NOTICE] switch_channel.c:1123 New Channel sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 [dd67a4f0-b013-4b57-abd6-2684d9011a2f]
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:5117 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State Change CS_NEW -> CS_INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Running State Change CS_INIT (Cur 2 Tot 4)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:624 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:97 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 SOFIA INIT
2023-03-19 09:44:04.358646 99.70% [INFO] sofia_glue.c:1654 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 sending invite call-id: (null)
2023-03-19 09:44:04.358646 99.70% [DEBUG] sofia_glue.c:1657 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 sending invite version: 1.10.9 -release-21-a615e85afc 64bit
Local SDP:
v=0
o=FreeSWITCH 1679201732 1679201733 IN IP6 <my v6 prefix>:100::3
s=FreeSWITCH
c=IN IP6 <my v6 prefix>:100::3
t=0 0
m=audio 17312 RTP/AVP 8 0 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:40 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 Standard INIT
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:48 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State Change CS_INIT -> CS_ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:624 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State INIT going to sleep
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Running State Change CS_ROUTING (Cur 2 Tot 4)
2023-03-19 09:44:04.358646 99.70% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 entering state [calling][0]
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] mod_sofia.c:158 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 SOFIA ROUTING
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_ivr_originate.c:67 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State ROUTING going to sleep
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 4)
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:659 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State CONSUME_MEDIA
2023-03-19 09:44:04.358646 99.70% [DEBUG] switch_core_state_machine.c:659 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State CONSUME_MEDIA going to sleep
2023-03-19 09:44:04.518647 99.70% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 entering state [proceeding][180]
2023-03-19 09:44:04.518647 99.70% [NOTICE] sofia.c:7598 Ring-Ready sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358!
2023-03-19 09:44:04.518647 99.70% [DEBUG] switch_channel.c:3494 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Callstate Change DOWN -> RINGING
2023-03-19 09:44:04.538634 99.70% [NOTICE] mod_sofia.c:2516 Ring-Ready sofia/external/<calling number>@185.8.92.11!
2023-03-19 09:44:04.538634 99.70% [DEBUG] sofia.c:7487 Channel sofia/external/<calling number>@185.8.92.11 entering state [early][180]
2023-03-19 09:44:04.538634 99.70% [NOTICE] switch_ivr_originate.c:565 Ring Ready sofia/external/<calling number>@185.8.92.11!
2023-03-19 09:44:34.018645 99.70% [NOTICE] switch_ivr_originate.c:3809 Hangup sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 [CS_CONSUME_MEDIA] [NO_ANSWER]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Running State Change CS_HANGUP (Cur 2 Tot 4)
2023-03-19 09:44:34.018645 99.70% [NOTICE] switch_ivr_originate.c:3049 Cannot create outgoing channel of type [user] cause: [NO_ANSWER]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_ivr_originate.c:4045 Originate Resulted in Error Cause: 19 [NO_ANSWER]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:844 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Callstate Change RINGING -> HANGUP
2023-03-19 09:44:34.018645 99.70% [INFO] mod_dptools.c:3637 Originate Failed. Cause: NO_ANSWER
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:846 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State HANGUP
2023-03-19 09:44:34.018645 99.70% [DEBUG] mod_sofia.c:468 Channel sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 hanging up, cause: NO_ANSWER
2023-03-19 09:44:34.018645 99.70% [DEBUG] mod_sofia.c:536 Sending CANCEL to sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 answer()
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:59 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 Standard HANGUP, cause: NO_ANSWER
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:846 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State HANGUP going to sleep
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:616 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State Change CS_HANGUP -> CS_REPORTING
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Running State Change CS_REPORTING (Cur 2 Tot 4)
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5582 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5582 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5443 Set telephone-event payload to 101@8000
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:932 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State REPORTING
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:3750 Set Codec sofia/external/<calling number>@185.8.92.11 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_codec.c:111 sofia/external/<calling number>@185.8.92.11 Original read codec set to PCMA:8
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:168 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 Standard REPORTING, cause: NO_ANSWER
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:932 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State REPORTING going to sleep
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5792 Set telephone-event payload to 101@8000
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:5850 sofia/external/<calling number>@185.8.92.11 Set 2833 dtmf send payload to 101 recv payload to 101
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:607 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State Change CS_REPORTING -> CS_DESTROY
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_session.c:1743 Session 4 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Locked, Waiting on external entities
2023-03-19 09:44:34.018645 99.70% [NOTICE] switch_core_session.c:1761 Session 4 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Ended
2023-03-19 09:44:34.018645 99.70% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 [CS_DESTROY]
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:8651 AUDIO RTP [sofia/external/<calling number>@185.8.92.11] 10.7.100.3 port 29090 -> 185.8.92.11 port 17162 codec: 8 ms: 20
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:735 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) Running State Change CS_DESTROY (Cur 1 Tot 4)
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_rtp.c:4399 Not using a timer
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:745 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State DESTROY
2023-03-19 09:44:34.018645 99.70% [DEBUG] mod_sofia.c:379 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 SOFIA DESTROY
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:175 sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358 Standard DESTROY
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_state_machine.c:745 (sofia/internal-ipv6/1001@[<my v6 prefix>:2:84fe:7640:aad2:91ac]:64358) State DESTROY going to sleep
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:8963 sofia/external/<calling number>@185.8.92.11 Set 2833 dtmf send payload to 101
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:8970 sofia/external/<calling number>@185.8.92.11 Set 2833 dtmf receive payload to 101
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:8993 sofia/external/<calling number>@185.8.92.11 Set rtp dtmf delay to 40
2023-03-19 09:44:34.018645 99.70% [NOTICE] sofia_media.c:90 Pre-Answer sofia/external/<calling number>@185.8.92.11!
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_channel.c:3566 (sofia/external/<calling number>@185.8.92.11) Callstate Change RINGING -> EARLY
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_core_media.c:8633 Audio params are unchanged for sofia/external/<calling number>@185.8.92.11.
2023-03-19 09:44:34.018645 99.70% [DEBUG] mod_sofia.c:913 Local SDP sofia/external/<calling number>@185.8.92.11:
v=0
o=FreeSWITCH 1679189984 1679189985 IN IP4 <my v4 ip>
s=FreeSWITCH
c=IN IP4 <my v4 ip>
t=0 0
m=audio 29090 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
2023-03-19 09:44:34.018645 99.70% [NOTICE] mod_dptools.c:1408 Channel [sofia/external/<calling number>@185.8.92.11] has been answered
2023-03-19 09:44:34.018645 99.70% [DEBUG] switch_channel.c:3893 (sofia/external/<calling number>@185.8.92.11) Callstate Change EARLY -> ACTIVE
2023-03-19 09:44:34.018645 99.70% [DEBUG] sofia.c:7487 Channel sofia/external/<calling number>@185.8.92.11 entering state [completed][200]
EXECUTE [depth=0] sofia/external/<calling number>@185.8.92.11 sleep(1000)
2023-03-19 09:44:34.038641 99.70% [DEBUG] sofia.c:7487 Channel sofia/external/<calling number>@185.8.92.11 entering state [ready][200]
2023-03-19 09:44:54.838652 99.67% [NOTICE] sofia.c:1065 Hangup sofia/external/<calling number>@185.8.92.11 [CS_EXECUTE] [NORMAL_CLEARING]
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_session.c:2973 sofia/external/<calling number>@185.8.92.11 skip receive message [PHONE_EVENT] (channel is hungup already)
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:647 (sofia/external/<calling number>@185.8.92.11) State EXECUTE going to sleep
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_HANGUP (Cur 1 Tot 4)
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:844 (sofia/external/<calling number>@185.8.92.11) Callstate Change ACTIVE -> HANGUP
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:846 (sofia/external/<calling number>@185.8.92.11) State HANGUP
2023-03-19 09:44:54.838652 99.67% [DEBUG] mod_sofia.c:468 Channel sofia/external/<calling number>@185.8.92.11 hanging up, cause: NORMAL_CLEARING
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:59 sofia/external/<calling number>@185.8.92.11 Standard HANGUP, cause: NORMAL_CLEARING
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:846 (sofia/external/<calling number>@185.8.92.11) State HANGUP going to sleep
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:616 (sofia/external/<calling number>@185.8.92.11) State Change CS_HANGUP -> CS_REPORTING
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_REPORTING (Cur 1 Tot 4)
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:932 (sofia/external/<calling number>@185.8.92.11) State REPORTING
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:168 sofia/external/<calling number>@185.8.92.11 Standard REPORTING, cause: NORMAL_CLEARING
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:932 (sofia/external/<calling number>@185.8.92.11) State REPORTING going to sleep
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:607 (sofia/external/<calling number>@185.8.92.11) State Change CS_REPORTING -> CS_DESTROY
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_session.c:1743 Session 3 (sofia/external/<calling number>@185.8.92.11) Locked, Waiting on external entities
2023-03-19 09:44:54.838652 99.67% [NOTICE] switch_core_session.c:1761 Session 3 (sofia/external/<calling number>@185.8.92.11) Ended
2023-03-19 09:44:54.838652 99.67% [NOTICE] switch_core_session.c:1765 Close Channel sofia/external/<calling number>@185.8.92.11 [CS_DESTROY]
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:735 (sofia/external/<calling number>@185.8.92.11) Running State Change CS_DESTROY (Cur 0 Tot 4)
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:745 (sofia/external/<calling number>@185.8.92.11) State DESTROY
2023-03-19 09:44:54.838652 99.67% [DEBUG] mod_sofia.c:379 sofia/external/<calling number>@185.8.92.11 SOFIA DESTROY
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:175 sofia/external/<calling number>@185.8.92.11 Standard DESTROY
2023-03-19 09:44:54.838652 99.67% [DEBUG] switch_core_state_machine.c:745 (sofia/external/<calling number>@185.8.92.11) State DESTROY going to sleep
Looking at a packet dump, it seems that I respond with a 200 OK to the invite from the provider, they send back an ACK, but no media is sent in either direction. Around 20 seconds later, the provider sends a BYE.
I’m seeing the same thing happen with 2 different SIP trunking providers. Can anyone help me figure out what’s going on?
