<action application="bridge" data="{sip_invite_domain=$${ogogon_proxy}}sofia/local/$1@$${ogogon_proxy}"/>
2019-12-26 16:10:05.019205 [NOTICE] switch_channel.c:1114 New Channel
sofia/local/101@192.168.1.22 [a9d46508-e127-ea11-99bc-c86000bcf23c]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/101@192.168.1.22) Running State Change CS_NEW (Cur 1 Tot 65)
2019-12-26 16:10:05.019205 [DEBUG] sofia.c:10164
sofia/local/101@192.168.1.22 receiving invite from 192.168.1.26:5064 version: 1.8.7 64bit
2019-12-26 16:10:05.019205 [DEBUG] sofia.c:7323 Channel
sofia/local/101@192.168.1.22 entering state [received][100]
2019-12-26 16:10:05.019205 [DEBUG] sofia.c:7333 Remote SDP:
v=0
o=101 8000 8000 IN IP4 192.168.1.26
s=SIP Call
c=IN IP4 192.168.1.26
t=0 0
m=audio 5110 RTP/AVP 0 8 4 18 9 97 2 123 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:2 G726-32/8000
a=rtpmap:123 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [iLBC:97:8000:20:0:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:2:8000:20:0:1]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [opus:123:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [opus:123:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [opus:123:48000:20:0:2]/[SPEEX:99:8000:20:24600:1]
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5427 Set telephone-event payload to 101@8000
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:3781 Set Codec
sofia/local/101@192.168.1.22 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-12-26 16:10:05.019205 [DEBUG] switch_core_codec.c:111
sofia/local/101@192.168.1.22 Original read codec set to PCMU:0
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5770 Set telephone-event payload to 101@8000
2019-12-26 16:10:05.019205 [DEBUG] switch_core_media.c:5828
sofia/local/101@192.168.1.22 Set 2833 dtmf send payload to 101 recv payload to 101
2019-12-26 16:10:05.019205 [DEBUG] sofia.c:7748 (
sofia/local/101@192.168.1.22) State Change CS_NEW -> CS_INIT
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:603 (
sofia/local/101@192.168.1.22) State NEW
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/101@192.168.1.22) Running State Change CS_INIT (Cur 1 Tot 65)
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:627 (
sofia/local/101@192.168.1.22) State INIT
2019-12-26 16:10:05.019205 [DEBUG] mod_sofia.c:93
sofia/local/101@192.168.1.22 SOFIA INIT
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:40
sofia/local/101@192.168.1.22 Standard INIT
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:48 (
sofia/local/101@192.168.1.22) State Change CS_INIT -> CS_ROUTING
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:627 (
sofia/local/101@192.168.1.22) State INIT going to sleep
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/101@192.168.1.22) Running State Change CS_ROUTING (Cur 1 Tot 65)
2019-12-26 16:10:05.019205 [DEBUG] switch_channel.c:2293 (
sofia/local/101@192.168.1.22) Callstate Change DOWN -> RINGING
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:643 (
sofia/local/101@192.168.1.22) State ROUTING
2019-12-26 16:10:05.019205 [DEBUG] mod_sofia.c:154
sofia/local/101@192.168.1.22 SOFIA ROUTING
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:236
sofia/local/101@192.168.1.22 Standard ROUTING
2019-12-26 16:10:05.019205 [INFO] mod_dialplan_xml.c:637 Processing 101 <101>->1234567 in context local
Dialplan:
sofia/local/101@192.168.1.22 parsing [local->local-account-hello] continue=false
Dialplan:
sofia/local/101@192.168.1.22 Regex (FAIL) [local-account-hello] destination_number(1234567) =~ /^100$/ break=on-false
Dialplan:
sofia/local/101@192.168.1.22 parsing [local->local-accounts] continue=false
Dialplan:
sofia/local/101@192.168.1.22 Regex (FAIL) [local-accounts] destination_number(1234567) =~ /^(10[1-3])$/ break=on-false
Dialplan:
sofia/local/101@192.168.1.22 parsing [local->uplink] continue=false
Dialplan:
sofia/local/101@192.168.1.22 Regex (PASS) [uplink] destination_number(1234567) =~ /^(\d+)$/ break=on-false
Dialplan:
sofia/local/101@192.168.1.22 Action set(effective_caller_id_number=fs)
Dialplan:
sofia/local/101@192.168.1.22 Action bridge(
{sip_invite_domain=pbx.ogogon.org}sofia ... ogogon.org)
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:286 (
sofia/local/101@192.168.1.22) State Change CS_ROUTING -> CS_EXECUTE
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:643 (
sofia/local/101@192.168.1.22) State ROUTING going to sleep
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/101@192.168.1.22) Running State Change CS_EXECUTE (Cur 1 Tot 65)
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:650 (
sofia/local/101@192.168.1.22) State EXECUTE
2019-12-26 16:10:05.019205 [DEBUG] mod_sofia.c:209
sofia/local/101@192.168.1.22 SOFIA EXECUTE
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:328
sofia/local/101@192.168.1.22 Standard EXECUTE
EXECUTE [depth=0]
sofia/local/101@192.168.1.22 set(effective_caller_id_number=fs)
2019-12-26 16:10:05.019205 [DEBUG] mod_dptools.c:1615 SET
sofia/local/101@192.168.1.22 [effective_caller_id_number]=[fs]
EXECUTE [depth=0]
sofia/local/101@192.168.1.22 bridge(
{sip_invite_domain=pbx.ogogon.org}sofia ... ogogon.org)
2019-12-26 16:10:05.019205 [DEBUG] switch_ivr_originate.c:2209 Parsing global variables
2019-12-26 16:10:05.019205 [NOTICE] switch_channel.c:1114 New Channel
sofia/local/1234567@pbx.ogogon.org [29bc6608-e127-ea11-99bc-c86000bcf23c]
2019-12-26 16:10:05.019205 [DEBUG] mod_sofia.c:5031 (
sofia/local/1234567@pbx.ogogon.org) State Change CS_NEW -> CS_INIT
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/1234567@pbx.ogogon.org) Running State Change CS_INIT (Cur 2 Tot 66)
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:627 (
sofia/local/1234567@pbx.ogogon.org) State INIT
2019-12-26 16:10:05.019205 [DEBUG] mod_sofia.c:93
sofia/local/1234567@pbx.ogogon.org SOFIA INIT
2019-12-26 16:10:05.019205 [DEBUG] sofia_glue.c:1315
sofia/local/1234567@pbx.ogogon.org sending invite version: 1.8.7 64bit
Local SDP:
v=0
o=FreeSWITCH 1577340903 1577340904 IN IP4 192.168.1.22
s=FreeSWITCH
c=IN IP4 192.168.1.22
t=0 0
m=audio 24902 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:40
sofia/local/1234567@pbx.ogogon.org Standard INIT
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:48 (
sofia/local/1234567@pbx.ogogon.org) State Change CS_INIT -> CS_ROUTING
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:627 (
sofia/local/1234567@pbx.ogogon.org) State INIT going to sleep
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/1234567@pbx.ogogon.org) Running State Change CS_ROUTING (Cur 2 Tot 66)
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:643 (
sofia/local/1234567@pbx.ogogon.org) State ROUTING
2019-12-26 16:10:05.019205 [DEBUG] mod_sofia.c:154
sofia/local/1234567@pbx.ogogon.org SOFIA ROUTING
2019-12-26 16:10:05.019205 [DEBUG] switch_ivr_originate.c:67 (
sofia/local/1234567@pbx.ogogon.org) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:643 (
sofia/local/1234567@pbx.ogogon.org) State ROUTING going to sleep
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/1234567@pbx.ogogon.org) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 66)
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:662 (
sofia/local/1234567@pbx.ogogon.org) State CONSUME_MEDIA
2019-12-26 16:10:05.019205 [DEBUG] switch_core_state_machine.c:662 (
sofia/local/1234567@pbx.ogogon.org) State CONSUME_MEDIA going to sleep
2019-12-26 16:10:05.019205 [DEBUG] sofia.c:7323 Channel
sofia/local/1234567@pbx.ogogon.org entering state [calling][0]
2019-12-26 16:10:07.040369 [ERR] sofia_reg.c:2645 Cannot locate any authentication credentials to complete an authentication request for realm '"asterisk"'2019-12-26 16:10:07.040369 [NOTICE] sofia_reg.c:2668 Hangup
sofia/local/1234567@pbx.ogogon.org [CS_CONSUME_MEDIA] [MANDATORY_IE_MISSING]
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/1234567@pbx.ogogon.org) Running State Change CS_HANGUP (Cur 2 Tot 66)
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:847 (
sofia/local/1234567@pbx.ogogon.org) Callstate Change DOWN -> HANGUP
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:849 (
sofia/local/1234567@pbx.ogogon.org) State HANGUP
2019-12-26 16:10:07.040369 [DEBUG] mod_sofia.c:460 Channel
sofia/local/1234567@pbx.ogogon.org hanging up, cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.040369 [DEBUG] mod_sofia.c:525 Sending CANCEL to
sofia/local/1234567@pbx.ogogon.org2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:60
sofia/local/1234567@pbx.ogogon.org Standard HANGUP, cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:849 (
sofia/local/1234567@pbx.ogogon.org) State HANGUP going to sleep
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:619 (
sofia/local/1234567@pbx.ogogon.org) State Change CS_HANGUP -> CS_REPORTING
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/1234567@pbx.ogogon.org) Running State Change CS_REPORTING (Cur 2 Tot 66)
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:935 (
sofia/local/1234567@pbx.ogogon.org) State REPORTING
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:174
sofia/local/1234567@pbx.ogogon.org Standard REPORTING, cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:935 (
sofia/local/1234567@pbx.ogogon.org) State REPORTING going to sleep
2019-12-26 16:10:07.040369 [DEBUG] switch_core_state_machine.c:610 (
sofia/local/1234567@pbx.ogogon.org) State Change CS_REPORTING -> CS_DESTROY
2019-12-26 16:10:07.040369 [DEBUG] switch_core_session.c:1726 Session 66 (
sofia/local/1234567@pbx.ogogon.org) Locked, Waiting on external entities
2019-12-26 16:10:07.059946 [DEBUG] switch_ivr_originate.c:3946 Originate Resulted in Error Cause: 96 [MANDATORY_IE_MISSING]
2019-12-26 16:10:07.059946 [NOTICE] switch_core_session.c:1744 Session 66 (
sofia/local/1234567@pbx.ogogon.org) Ended
2019-12-26 16:10:07.059946 [NOTICE] switch_core_session.c:1748 Close Channel
sofia/local/1234567@pbx.ogogon.org [CS_DESTROY]
2019-12-26 16:10:07.059946 [INFO] mod_dptools.c:3582 Originate Failed. Cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.059946 [NOTICE] switch_channel.c:4901 Hangup
sofia/local/101@192.168.1.22 [CS_EXECUTE] [MANDATORY_IE_MISSING]
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:738 (
sofia/local/1234567@pbx.ogogon.org) Running State Change CS_DESTROY (Cur 1 Tot 66)
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:748 (
sofia/local/1234567@pbx.ogogon.org) State DESTROY
2019-12-26 16:10:07.059946 [DEBUG] mod_sofia.c:365
sofia/local/1234567@pbx.ogogon.org SOFIA DESTROY
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:181
sofia/local/1234567@pbx.ogogon.org Standard DESTROY
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:748 (
sofia/local/1234567@pbx.ogogon.org) State DESTROY going to sleep
2019-12-26 16:10:07.059946 [DEBUG] switch_core_session.c:2905
sofia/local/101@192.168.1.22 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:650 (
sofia/local/101@192.168.1.22) State EXECUTE going to sleep
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/101@192.168.1.22) Running State Change CS_HANGUP (Cur 1 Tot 66)
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:847 (
sofia/local/101@192.168.1.22) Callstate Change RINGING -> HANGUP
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:849 (
sofia/local/101@192.168.1.22) State HANGUP
2019-12-26 16:10:07.059946 [DEBUG] mod_sofia.c:460 Channel
sofia/local/101@192.168.1.22 hanging up, cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.059946 [DEBUG] mod_sofia.c:600 Responding to INVITE with: 480
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:60
sofia/local/101@192.168.1.22 Standard HANGUP, cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:849 (
sofia/local/101@192.168.1.22) State HANGUP going to sleep
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:619 (
sofia/local/101@192.168.1.22) State Change CS_HANGUP -> CS_REPORTING
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:584 (
sofia/local/101@192.168.1.22) Running State Change CS_REPORTING (Cur 1 Tot 66)
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:935 (
sofia/local/101@192.168.1.22) State REPORTING
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:174
sofia/local/101@192.168.1.22 Standard REPORTING, cause: MANDATORY_IE_MISSING
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:935 (
sofia/local/101@192.168.1.22) State REPORTING going to sleep
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:610 (
sofia/local/101@192.168.1.22) State Change CS_REPORTING -> CS_DESTROY
2019-12-26 16:10:07.059946 [DEBUG] switch_core_session.c:1726 Session 65 (
sofia/local/101@192.168.1.22) Locked, Waiting on external entities
2019-12-26 16:10:07.059946 [NOTICE] switch_core_session.c:1744 Session 65 (
sofia/local/101@192.168.1.22) Ended
2019-12-26 16:10:07.059946 [NOTICE] switch_core_session.c:1748 Close Channel
sofia/local/101@192.168.1.22 [CS_DESTROY]
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:738 (
sofia/local/101@192.168.1.22) Running State Change CS_DESTROY (Cur 0 Tot 66)
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:748 (
sofia/local/101@192.168.1.22) State DESTROY
2019-12-26 16:10:07.059946 [DEBUG] mod_sofia.c:365
sofia/local/101@192.168.1.22 SOFIA DESTROY
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:181
sofia/local/101@192.168.1.22 Standard DESTROY
2019-12-26 16:10:07.059946 [DEBUG] switch_core_state_machine.c:748 (
sofia/local/101@192.168.1.22) State DESTROY going to sleep
Ogogon.