first attempt incoming call failed, but second is through

Hi All

I hope somebody here can help to point out where i'm get wrong with the ACL or anything related that i don't know
I have a PSTN trunk from my SIP provider, i have configure the gateway to the provider without register as it does not required, all seems to be OK with outbound call from extensions.
But the issue is:

For the first attempt inbound call i get issue with call failed ( see log) but if i retry again then the call is through and extension ring
So somebody can help me to figure out what issue happened please ?

I appreciate your help.
------------------------------------------------------------
2019-05-11 06:52:57.109620 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/0906366151@113.164.240.242:5060 [529b8a71-ae3c-499f-9f22-2088bfc67c5b]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242:5060) Running State Change CS_NEW (Cur 1 Tot 58)
2019-05-11 06:52:57.109620 [DEBUG] sofia.c:10092 sofia/internal/0906366151@113.164.240.242:5060 receiving invite from 113.164.240.242:5060 version: 1.8.5 -6-31281a0bf1 64bit
2019-05-11 06:52:57.109620 [DEBUG] sofia.c:10208 IP 113.164.240.242 Approved by acl "domains[]". Access Granted.
2019-05-11 06:52:57.109620 [DEBUG] sofia.c:7291 Channel sofia/internal/0906366151@113.164.240.242:5060 entering state [received][100]
2019-05-11 06:52:57.109620 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=CiscoSystemsSIP-GW-UserAgent 693 2146 IN IP4 113.164.240.242
s=SIP Call
c=IN IP4 113.164.240.242
t=0 0
m=audio 58478 RTP/AVP 18 4 0 8 101 19
c=IN IP4 113.164.240.242
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:4 G723/8000
a=fmtp:4 bitrate=6.3;annexa=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:19 CN/8000

2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:4841 Activate Buggy RFC2833 Mode!
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:30:6300:1]/[G722:9:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:30:6300:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:30:6300:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/0906366151@113.164.240.242:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-05-11 06:52:57.109620 [DEBUG] switch_core_codec.c:111 sofia/internal/0906366151@113.164.240.242:5060 Original read codec set to PCMU:0
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
2019-05-11 06:52:57.109620 [DEBUG] switch_core_media.c:5795 sofia/internal/0906366151@113.164.240.242:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2019-05-11 06:52:57.109620 [DEBUG] sofia.c:7716 (sofia/internal/0906366151@113.164.240.242:5060) State Change CS_NEW -> CS_INIT
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/0906366151@113.164.240.242:5060) State NEW
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242:5060) Running State Change CS_INIT (Cur 1 Tot 58)
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/0906366151@113.164.240.242:5060) State INIT
2019-05-11 06:52:57.109620 [DEBUG] mod_sofia.c:93 sofia/internal/0906366151@113.164.240.242:5060 SOFIA INIT
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:40 sofia/internal/0906366151@113.164.240.242:5060 Standard INIT
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/0906366151@113.164.240.242:5060) State Change CS_INIT -> CS_ROUTING
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/0906366151@113.164.240.242:5060) State INIT going to sleep
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242:5060) Running State Change CS_ROUTING (Cur 1 Tot 58)
2019-05-11 06:52:57.109620 [DEBUG] switch_channel.c:2249 (sofia/internal/0906366151@113.164.240.242:5060) Callstate Change DOWN -> RINGING
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/0906366151@113.164.240.242:5060) State ROUTING
2019-05-11 06:52:57.109620 [DEBUG] mod_sofia.c:154 sofia/internal/0906366151@113.164.240.242:5060 SOFIA ROUTING
2019-05-11 06:52:57.109620 [DEBUG] switch_core_state_machine.c:236 sofia/internal/0906366151@113.164.240.242:5060 Standard ROUTING
2019-05-11 06:52:57.109620 [INFO] mod_dialplan_xml.c:637 Processing 0906366151 <0906366151>->02877766698 in context public
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 parsing [public->caller-details] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action export(call_direction=inbound) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 export(call_direction=inbound)
2019-05-11 06:52:57.129574 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action set(caller_destination=${destination_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 set(caller_destination=02877766698)
2019-05-11 06:52:57.129574 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242:5060 [caller_destination]=[02877766698]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 set(caller_id_name=0906366151)
2019-05-11 06:52:57.129574 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242:5060 [caller_id_name]=[0906366151]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action set(caller_id_number=${caller_id_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 set(caller_id_number=0906366151)
2019-05-11 06:52:57.129574 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242:5060 [caller_id_number]=[0906366151]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 parsing [public->842877766501] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Regex (FAIL) [842877766501] destination_number(02877766698) =~ /^(842877766501)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 parsing [public->842877766698] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Regex (FAIL) [842877766698] destination_number(02877766698) =~ /^(842877766698)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 parsing [public->61480015233] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Regex (FAIL) [61480015233] destination_number(02877766698) =~ /^\+(61480015233)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 parsing [public->12025179591] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Regex (FAIL) [12025179591] destination_number(02877766698) =~ /^\+(12025179591)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 parsing [public->not-found] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Regex (PASS) [not-found] () =~ // break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action export(call_direction=inbound) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 export(call_direction=inbound)
2019-05-11 06:52:57.129574 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action set(domain_name=sip.vietvan.net) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 set(domain_name=sip.vietvan.net)
2019-05-11 06:52:57.129574 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242:5060 [domain_name]=[sip.vietvan.net]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 set(call_direction=inbound)
2019-05-11 06:52:57.129574 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242:5060 [call_direction]=[inbound]
Dialplan: sofia/internal/0906366151@113.164.240.242:5060 Action log([inbound routes] 404 not found ${sip_network_ip}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242:5060 log([inbound routes] 404 not found 113.164.240.242)
2019-05-11 06:52:57.129574 [DEBUG] mod_dptools.c:1792 routes] 404 not found 113.164.240.242
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/0906366151@113.164.240.242:5060) State Change CS_ROUTING -> CS_EXECUTE
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/0906366151@113.164.240.242:5060) State ROUTING going to sleep
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242:5060) Running State Change CS_EXECUTE (Cur 1 Tot 58)
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/0906366151@113.164.240.242:5060) State EXECUTE
2019-05-11 06:52:57.129574 [DEBUG] mod_sofia.c:209 sofia/internal/0906366151@113.164.240.242:5060 SOFIA EXECUTE
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:328 sofia/internal/0906366151@113.164.240.242:5060 Standard EXECUTE
2019-05-11 06:52:57.129574 [NOTICE] switch_core_state_machine.c:385 sofia/internal/0906366151@113.164.240.242:5060 has executed the last dialplan instruction, hanging up.
2019-05-11 06:52:57.129574 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/0906366151@113.164.240.242:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/0906366151@113.164.240.242:5060) State EXECUTE going to sleep
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242:5060) Running State Change CS_HANGUP (Cur 1 Tot 58)
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/0906366151@113.164.240.242:5060) Callstate Change RINGING -> HANGUP
2019-05-11 06:52:57.129574 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/0906366151@113.164.240.242:5060) State HANGUP
2019-05-11 06:52:57.129574 [DEBUG] mod_sofia.c:449 Channel sofia/internal/0906366151@113.164.240.242:5060 hanging up, cause: NORMAL_CLEARING
2019-05-11 06:52:57.129574 [DEBUG] mod_sofia.c:589 Responding to INVITE with: 480
.....
 

Attached Files:

@DigitalDaz : I did, but if i don't define the destination with DID in full form of country code + area code + number then the call will never hit the inbound route call, sngrep show the INVITE from trunk provider is 842877766698 not just 02877766698

i just wonder why the second time just the same INVITE from provider then the inbound route hit and transfer to my extension

below is the log of second attempt and the 3rd, 4th.... they all hit the inbound route successfully

i can live the 2nd attempt but other people will get confused with 1st call error, it's a bit annoyance

Thank for talk to me
-----------------------------------------------------------------
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_NEW (Cur 1 Tot 14)
2019-05-11 16:37:57.017316 [DEBUG] sofia.c:10092 sofia/internal/0906366151@113.164.240.242 receiving invite from 113.164.240.242:5060 version: 1.8.5 -6-31281a0bf1 64bit
2019-05-11 16:37:57.017316 [DEBUG] sofia.c:10208 IP 113.164.240.242 Approved by acl "domains[]". Access Granted.
2019-05-11 16:37:57.017316 [DEBUG] sofia.c:7291 Channel sofia/internal/0906366151@113.164.240.242 entering state [received][100]
2019-05-11 16:37:57.017316 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=CiscoSystemsSIP-GW-UserAgent 9191 757 IN IP4 113.164.240.242
s=SIP Call
c=IN IP4 113.164.240.242
t=0 0
m=audio 52404 RTP/AVP 18 4 0 8 101 19
c=IN IP4 113.164.240.242
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:4 G723/8000
a=fmtp:4 bitrate=6.3;annexa=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:19 CN/8000

2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:4841 Activate Buggy RFC2833 Mode!
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:30:6300:1]/[G722:9:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:30:6300:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G723:4:8000:30:6300:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/0906366151@113.164.240.242 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-05-11 16:37:57.017316 [DEBUG] switch_core_codec.c:111 sofia/internal/0906366151@113.164.240.242 Original read codec set to PCMU:0
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
2019-05-11 16:37:57.017316 [DEBUG] switch_core_media.c:5795 sofia/internal/0906366151@113.164.240.242 Set 2833 dtmf send payload to 101 recv payload to 101
2019-05-11 16:37:57.017316 [DEBUG] sofia.c:7716 (sofia/internal/0906366151@113.164.240.242) State Change CS_NEW -> CS_INIT
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/0906366151@113.164.240.242) State NEW
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_INIT (Cur 1 Tot 14)
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/0906366151@113.164.240.242) State INIT
2019-05-11 16:37:57.017316 [DEBUG] mod_sofia.c:93 sofia/internal/0906366151@113.164.240.242 SOFIA INIT
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:40 sofia/internal/0906366151@113.164.240.242 Standard INIT
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/0906366151@113.164.240.242) State Change CS_INIT -> CS_ROUTING
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/0906366151@113.164.240.242) State INIT going to sleep
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_ROUTING (Cur 1 Tot 14)
2019-05-11 16:37:57.017316 [DEBUG] switch_channel.c:2249 (sofia/internal/0906366151@113.164.240.242) Callstate Change DOWN -> RINGING
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/0906366151@113.164.240.242) State ROUTING
2019-05-11 16:37:57.017316 [DEBUG] mod_sofia.c:154 sofia/internal/0906366151@113.164.240.242 SOFIA ROUTING
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:236 sofia/internal/0906366151@113.164.240.242 Standard ROUTING
2019-05-11 16:37:57.017316 [INFO] mod_dialplan_xml.c:637 Processing 0906366151 <0906366151>->842877766698 in context public
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [public->caller-details] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Action export(call_direction=inbound) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 export(call_direction=inbound)
2019-05-11 16:37:57.017316 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(caller_destination=${destination_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(caller_destination=842877766698)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [caller_destination]=[842877766698]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(caller_id_name=0906366151)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [caller_id_name]=[0906366151]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(caller_id_number=${caller_id_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(caller_id_number=0906366151)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [caller_id_number]=[0906366151]
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [public->842877766698] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [842877766698] destination_number(842877766698) =~ /^(842877766698)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action export(call_direction=inbound) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 export(call_direction=inbound)
2019-05-11 16:37:57.017316 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(domain_uuid=c1ca509a-ef4e-4934-acc2-c9f06d77c60b) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(domain_uuid=c1ca509a-ef4e-4934-acc2-c9f06d77c60b)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [domain_uuid]=[c1ca509a-ef4e-4934-acc2-c9f06d77c60b]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(domain_name=sip.vietvan.net) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(domain_name=sip.vietvan.net)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [domain_name]=[sip.vietvan.net]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(continue_on_fail=true)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(tone_detect_hits=1)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(execute_on_tone_detect=transfer 7000 XML ${domain_name})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action tone_detect(fax 1100 r +5000)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action answer()
Dialplan: sofia/internal/0906366151@113.164.240.242 Action sleep(3000)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action transfer(1001 XML sip.vietvan.net)
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/0906366151@113.164.240.242) State Change CS_ROUTING -> CS_EXECUTE
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/0906366151@113.164.240.242) State ROUTING going to sleep
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_EXECUTE (Cur 1 Tot 14)
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/0906366151@113.164.240.242) State EXECUTE
2019-05-11 16:37:57.017316 [DEBUG] mod_sofia.c:209 sofia/internal/0906366151@113.164.240.242 SOFIA EXECUTE
2019-05-11 16:37:57.017316 [DEBUG] switch_core_state_machine.c:328 sofia/internal/0906366151@113.164.240.242 Standard EXECUTE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(hangup_after_bridge=true)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/0906366151@113.164.240.242 set(continue_on_fail=true)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [continue_on_fail]=[true]
EXECUTE sofia/internal/0906366151@113.164.240.242 set(tone_detect_hits=1)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [tone_detect_hits]=[1]
EXECUTE sofia/internal/0906366151@113.164.240.242 set(execute_on_tone_detect=transfer 7000 XML sip.vietvan.net)
2019-05-11 16:37:57.017316 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [execute_on_tone_detect]=[transfer 7000 XML sip.vietvan.net]
2019-05-11 16:37:57.017316 [DEBUG] switch_core_session.c:2710 Application tone_detect Requires media! pre_answering channel sofia/internal/0906366151@113.164.240.242
2019-05-11 16:37:57.017316 [INFO] switch_core_session.c:2712 Sending early media
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/0906366151@113.164.240.242] 192.168.99.97 port 17642 -> 113.164.240.242 port 52404 codec: 0 ms: 20
2019-05-11 16:37:57.037270 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media.c:8815 sofia/internal/0906366151@113.164.240.242 Set 2833 dtmf send payload to 101
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media.c:8822 sofia/internal/0906366151@113.164.240.242 Set 2833 dtmf receive payload to 101
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media.c:8845 sofia/internal/0906366151@113.164.240.242 Set rtp dtmf delay to 40
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media.c:8851 Set comfort noise payload to 19
2019-05-11 16:37:57.037270 [DEBUG] mod_sofia.c:2505 Ring SDP:
v=0
o=FreeSWITCH 1557549835 1557549836 IN IP4 14.161.40.203
s=FreeSWITCH
c=IN IP4 14.161.40.203
t=0 0
m=audio 17642 RTP/AVP 0 101 19
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:19 CN/8000
a=ptime:20
a=sendrecv

2019-05-11 16:37:57.037270 [NOTICE] mod_sofia.c:2508 Pre-Answer sofia/internal/0906366151@113.164.240.242!
2019-05-11 16:37:57.037270 [DEBUG] switch_channel.c:3482 (sofia/internal/0906366151@113.164.240.242) Callstate Change RINGING -> EARLY
EXECUTE sofia/internal/0906366151@113.164.240.242 tone_detect(fax 1100 r +5000)
2019-05-11 16:37:57.037270 [NOTICE] mod_dptools.c:2234 Enabling tone detection 'fax' '1100'
2019-05-11 16:37:57.037270 [DEBUG] switch_ivr_async.c:3971 Adding tone spec 1100 index 0 hits 1
2019-05-11 16:37:57.037270 [DEBUG] sofia.c:7291 Channel sofia/internal/0906366151@113.164.240.242 entering state [early][183]
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/0906366151@113.164.240.242
EXECUTE sofia/internal/0906366151@113.164.240.242 answer()
2019-05-11 16:37:57.037270 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/internal/0906366151@113.164.240.242.
2019-05-11 16:37:57.037270 [DEBUG] mod_sofia.c:882 Local SDP sofia/internal/0906366151@113.164.240.242:
v=0
o=FreeSWITCH 1557549835 1557549837 IN IP4 14.161.40.203
s=FreeSWITCH
c=IN IP4 14.161.40.203
t=0 0
m=audio 17642 RTP/AVP 0 101 19
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:19 CN/8000
a=ptime:20
a=sendrecv

2019-05-11 16:37:57.037270 [NOTICE] mod_dptools.c:1360 Channel [sofia/internal/0906366151@113.164.240.242] has been answered
2019-05-11 16:37:57.037270 [DEBUG] switch_channel.c:3781 (sofia/internal/0906366151@113.164.240.242) Callstate Change EARLY -> ACTIVE
2019-05-11 16:37:57.037270 [DEBUG] sofia.c:7291 Channel sofia/internal/0906366151@113.164.240.242 entering state [completed][200]
EXECUTE sofia/internal/0906366151@113.164.240.242 sleep(3000)
2019-05-11 16:37:57.057280 [DEBUG] sofia.c:7291 Channel sofia/internal/0906366151@113.164.240.242 entering state [ready][200]
2019-05-11 16:37:57.137301 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
2019-05-11 16:37:57.137301 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2019-05-11 16:37:57.597313 [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 80
EXECUTE sofia/internal/0906366151@113.164.240.242 transfer(1001 XML sip.vietvan.net)
2019-05-11 16:38:00.037320 [DEBUG] switch_ivr.c:2207 (sofia/internal/0906366151@113.164.240.242) State Change CS_EXECUTE -> CS_ROUTING
2019-05-11 16:38:00.037320 [NOTICE] switch_ivr.c:2214 Transfer sofia/internal/0906366151@113.164.240.242 to XML[1001@sip.vietvan.net]
2019-05-11 16:38:00.037320 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/0906366151@113.164.240.242) State EXECUTE going to sleep
2019-05-11 16:38:00.037320 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_ROUTING (Cur 1 Tot 14)
2019-05-11 16:38:00.037320 [DEBUG] switch_channel.c:2249 (sofia/internal/0906366151@113.164.240.242) Callstate Change ACTIVE -> RINGING
2019-05-11 16:38:00.037320 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/0906366151@113.164.240.242) State ROUTING
2019-05-11 16:38:00.037320 [DEBUG] mod_sofia.c:154 sofia/internal/0906366151@113.164.240.242 SOFIA ROUTING
2019-05-11 16:38:00.037320 [DEBUG] switch_core_state_machine.c:236 sofia/internal/0906366151@113.164.240.242 Standard ROUTING
2019-05-11 16:38:00.037320 [INFO] mod_dialplan_xml.c:637 Processing 0906366151 <0906366151>->1001 in context sip.vietvan.net
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->user_exists] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(user_exists=true)
2019-05-11 16:38:00.037320 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [user_exists]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(extension_uuid=bc28c04d-ff23-4f4b-804b-6a18b56af17c)
2019-05-11 16:38:00.037320 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [extension_uuid]=[bc28c04d-ff23-4f4b-804b-6a18b56af17c]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(hold_music=local_stream://default)
2019-05-11 16:38:00.037320 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [hold_music]=[local_stream://default]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_all_enabled=false)
2019-05-11 16:38:00.037320 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_all_enabled]=[false]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_all_destination=)
2019-05-11 16:38:00.037320 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_busy_enabled=false)
2019-05-11 16:38:00.037320 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_busy_enabled]=[false]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_busy_destination=)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_no_answer_enabled=true)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_no_answer_enabled]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_no_answer_destination=0906366151)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_no_answer_destination]=[0906366151]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_user_not_registered_enabled=true)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_user_not_registered_enabled]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_user_not_registered_destination=0906366151)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_user_not_registered_destination]=[0906366151]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(forward_all_enabled=false)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [forward_all_enabled]=[false]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(do_not_disturb=false)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [do_not_disturb]=[false]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(call_timeout=30)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [call_timeout]=[30]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(missed_call_app=email)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [missed_call_app]=
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(missed_call_data=quangleehong@gmail.com)
2019-05-11 16:38:00.057262 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [missed_call_data]=[quangleehong@gmail.com]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(toll_allow=)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [toll_allow]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(call_screen_enabled=false)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [call_screen_enabled]=[false]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(user_record=all)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [user_record]=[all]
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->caller-details] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [caller-details] ${caller_destination}(842877766698) =~ /^$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->variables] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->call-direction] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->user_record] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(from_user_exists=false)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [from_user_exists]=[false]
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(record_session=true) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(record_session=true)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [record_session]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(record_path=/var/lib/freeswitch/recordings/sip.vietvan.net/archive/2019/May/11)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [record_path]=[/var/lib/freeswitch/recordings/sip.vietvan.net/archive/2019/May/11]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(record_name=${uuid}.${record_ext}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(record_name=756464c8-2671-4808-bde3-ef8fc5ab2064.wav)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [record_name]=[756464c8-2671-4808-bde3-ef8fc5ab2064.wav]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(recording_follow_transfer=true) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(recording_follow_transfer=true)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [recording_follow_transfer]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(record_append=true) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(record_append=true)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [record_append]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(record_in_progress=true) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(record_in_progress=true)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [record_in_progress]=[true]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(${uuid_record ${uuid} start ${record_path}/${record_name}})
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->redial] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->speed_dial] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [speed_dial] destination_number(1001) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->default_caller_id] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(emergency_caller_id_name=)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(emergency_caller_id_number=)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(outbound_caller_id_name=)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [outbound_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 set(outbound_caller_id_number=)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [outbound_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->indochina-telecom-trunk-QuangLe.d711] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [indochina-telecom-trunk-QuangLe.d711] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->indochina-telecom-trunk-ChuongTV-d711] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [indochina-telecom-trunk-ChuongTV-d711] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->twillio-sip-trunk-aus.11d] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [twillio-sip-trunk-aus.11d] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->outbound-route-cleverhub] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [outbound-route-cleverhub] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->twillio-sip-trunk-us.11d] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [twillio-sip-trunk-us.11d] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->US IVR] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [US IVR] destination_number(1001) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->IVR menu] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [IVR menu] destination_number(1001) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->agent_status] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [agent_status] destination_number(1001) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->agent_status_id] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [agent_status_id] destination_number(1001) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->group-intercept] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->page-extension] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [page-extension] destination_number(1001) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->eavesdrop] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^\*33(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->call_privacy] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call_privacy] destination_number(1001) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->call_return] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->intercept-ext] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->extension_queue] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [extension_queue] destination_number(1001) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [intercept-ext-polycom] destination_number(1001) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->dx] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [dx] destination_number(1001) =~ /^dx$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->send_to_voicemail] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [send_to_voicemail] destination_number(1001) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->VietvanFax-Server] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [VietvanFax-Server] destination_number(1001) =~ /^7000$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->att_xfer] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [att_xfer] destination_number(1001) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->extension-to-voicemail] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [extension-to-voicemail] username(0906366151) =~ /^0906366151$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [extension-to-voicemail] destination_number(1001) =~ /^0906366151$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->xfer_vm] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [xfer_vm] destination_number(1001) =~ /^xfer_vm$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->vmain] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [vmain] destination_number(1001) =~ /^vmain$|^\*4000$|^\*98$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [vmain] destination_number(1001) =~ /^(vmain$|^\*4000$|^\*98)(\d{2,12})$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->vmain_user] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [vmain_user] destination_number(1001) =~ /^\*97$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->is_transfer] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [is_transfer] destination_number(1001) =~ /^is_transfer$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->Voice-Conference] continue=
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [Voice-Conference] destination_number(1001) =~ /^(conf\+)?3000$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->cf] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [cf] destination_number(1001) =~ /^cf$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->delay_echo] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [delay_echo] destination_number(1001) =~ /^\*9195$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->echo] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [echo] destination_number(1001) =~ /^\*9196$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->milliwatt] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [milliwatt] destination_number(1001) =~ /^\*9197$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->is_zrtp_secure] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 ANTI-Action eval(not_secure)
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->tone_stream] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [tone_stream] destination_number(1001) =~ /^\*9198$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->is_secure] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->hold_music] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [hold_music] destination_number(1001) =~ /^\*9664$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->recordings] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [recordings] destination_number(1001) =~ /^\*(732)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->directory] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [directory] destination_number(1001) =~ /^\*411$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->wake-up] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [wake-up] destination_number(1001) =~ /^\*(925)$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->valet_park] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [valet_park] destination_number(1001) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [valet_park] destination_number(1001) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [valet_park] destination_number(1001) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->operator] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [operator] destination_number(1001) =~ /^0$|^operator$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->operator-forward] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [operator-forward] destination_number(1001) =~ /^\*000$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->do-not-disturb] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [do-not-disturb] destination_number(1001) =~ /^\*77$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [do-not-disturb] destination_number(1001) =~ /^\*78$|\*363$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [do-not-disturb] destination_number(1001) =~ /^\*79$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [do-not-disturb] destination_number(1001) =~ /^dnd\+0906366151$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->call-forward] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call-forward] destination_number(1001) =~ /^\*72$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call-forward] destination_number(1001) =~ /^\*73$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call-forward] destination_number(1001) =~ /^\*74$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call-forward] destination_number(1001) =~ /^forward\+(\Q0906366151\E)(?:\/(\d+))?$/ break=on-true
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->call forward all] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [call forward all] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call forward all] ${forward_all_enabled}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->follow-me] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [follow-me] destination_number(1001) =~ /^\*21$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->talking clock date and time] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [talking clock date and time] destination_number(1001) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->talking clock time] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [talking clock time] destination_number(1001) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->talking clock date] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [talking clock date] destination_number(1001) =~ /^\*9171$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->call_screen] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->local_extension] continue=true
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action export(dialed_extension=${destination_number}) INLINE
EXECUTE sofia/internal/0906366151@113.164.240.242 export(dialed_extension=1001)
2019-05-11 16:38:00.077281 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1001]
Dialplan: sofia/internal/0906366151@113.164.240.242 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [local_extension] () =~ // break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(continue_on_fail=true)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(api_hangup_hook=lua app.lua hangup)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action export(domain_name=${domain_name})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action bridge(user/${destination_number}@${domain_name})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action lua(app.lua failure_handler)
Dialplan: sofia/internal/0906366151@113.164.240.242 parsing [sip.vietvan.net->voicemail] continue=false
Dialplan: sofia/internal/0906366151@113.164.240.242 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(record_append=false)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(voicemail_action=save)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(voicemail_id=${destination_number})
Dialplan: sofia/internal/0906366151@113.164.240.242 Action set(voicemail_profile=default)
Dialplan: sofia/internal/0906366151@113.164.240.242 Action lua(app.lua voicemail)
2019-05-11 16:38:00.077281 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/0906366151@113.164.240.242) State Change CS_ROUTING -> CS_EXECUTE
2019-05-11 16:38:00.077281 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/0906366151@113.164.240.242) State ROUTING going to sleep
2019-05-11 16:38:00.077281 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_EXECUTE (Cur 1 Tot 14)
2019-05-11 16:38:00.077281 [DEBUG] switch_channel.c:2251 (sofia/internal/0906366151@113.164.240.242) Callstate Change RINGING -> ACTIVE
2019-05-11 16:38:00.077281 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/0906366151@113.164.240.242) State EXECUTE
2019-05-11 16:38:00.077281 [DEBUG] mod_sofia.c:209 sofia/internal/0906366151@113.164.240.242 SOFIA EXECUTE
2019-05-11 16:38:00.077281 [DEBUG] switch_core_state_machine.c:328 sofia/internal/0906366151@113.164.240.242 Standard EXECUTE
EXECUTE sofia/internal/0906366151@113.164.240.242 export(origination_callee_id_name=1001)
2019-05-11 16:38:00.077281 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[1001]
EXECUTE sofia/internal/0906366151@113.164.240.242 set(RFC2822_DATE=Sat, 11 May 2019 16:38:00 +0700)
2019-05-11 16:38:00.077281 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [RFC2822_DATE]=[Sat, 11 May 2019 16:38:00 +0700]
2019-05-11 16:38:00.097264 [DEBUG] switch_ivr_async.c:1325 Record session sample rate: 8000 -> 8000
2019-05-11 16:38:00.097264 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/0906366151@113.164.240.242
EXECUTE sofia/internal/0906366151@113.164.240.242 set(+OK Success
)
2019-05-11 16:38:00.097264 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [+OK Success
]=[UNDEF]
EXECUTE sofia/internal/0906366151@113.164.240.242 hash(insert/sip.vietvan.net-last_dial/0906366151/1001)
EXECUTE sofia/internal/0906366151@113.164.240.242 eval(not_secure)
EXECUTE sofia/internal/0906366151@113.164.240.242 limit(hash sip.vietvan.net 1001 )
2019-05-11 16:38:00.097264 [DEBUG] switch_limit.c:126 incr called: sip.vietvan.net_1001 max:-1, interval:0
2019-05-11 16:38:00.097264 [DEBUG] mod_hash.c:194 Usage for sip.vietvan.net_1001 is now 1
EXECUTE sofia/internal/0906366151@113.164.240.242 set(hangup_after_bridge=true)
2019-05-11 16:38:00.097264 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/0906366151@113.164.240.242 set(continue_on_fail=true)
2019-05-11 16:38:00.097264 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [continue_on_fail]=[true]
EXECUTE sofia/internal/0906366151@113.164.240.242 hash(insert/sip.vietvan.net-call_return/1001/0906366151)
EXECUTE sofia/internal/0906366151@113.164.240.242 hash(insert/sip.vietvan.net-last_dial_ext/1001/756464c8-2671-4808-bde3-ef8fc5ab2064)
EXECUTE sofia/internal/0906366151@113.164.240.242 set(called_party_call_group=Family Users)
2019-05-11 16:38:00.097264 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [called_party_call_group]=[Family Users]
EXECUTE sofia/internal/0906366151@113.164.240.242 hash(insert/sip.vietvan.net-last_dial/Family Users/756464c8-2671-4808-bde3-ef8fc5ab2064)
EXECUTE sofia/internal/0906366151@113.164.240.242 set(api_hangup_hook=lua app.lua hangup)
2019-05-11 16:38:00.097264 [DEBUG] mod_dptools.c:1598 SET sofia/internal/0906366151@113.164.240.242 [api_hangup_hook]=[lua app.lua hangup]
EXECUTE sofia/internal/0906366151@113.164.240.242 export(domain_name=sip.vietvan.net)
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=[sip.vietvan.net]
EXECUTE sofia/internal/0906366151@113.164.240.242 bridge(user/1001@sip.vietvan.net)
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1823 (sofia/internal/0906366151@113.164.240.242) Callstate Change ACTIVE -> RING_WAIT
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [call_direction]=[inbound] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [call_direction]=[inbound] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [dialed_extension]=[1001] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [origination_callee_id_name]=[1001] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [domain_name]=[sip.vietvan.net] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [call_direction]=[inbound] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [call_direction]=[inbound] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [dialed_extension]=[1001] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [origination_callee_id_name]=[1001] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_channel.c:1250 sofia/internal/0906366151@113.164.240.242 EXPORTING[export_vars] [domain_name]=[sip.vietvan.net] to event
2019-05-11 16:38:00.097264 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
2019-05-11 16:38:00.097264 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@35.185.177.49:5060 [1768b69c-d256-45a3-b34e-c8d094049689]
2019-05-11 16:38:00.097264 [DEBUG] mod_sofia.c:5019 (sofia/internal/1001@35.185.177.49:5060) State Change CS_NEW -> CS_INIT
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@35.185.177.49:5060) Running State Change CS_INIT (Cur 2 Tot 15)
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@35.185.177.49:5060) State INIT
2019-05-11 16:38:00.097264 [DEBUG] mod_sofia.c:93 sofia/internal/1001@35.185.177.49:5060 SOFIA INIT
2019-05-11 16:38:00.097264 [DEBUG] sofia_glue.c:1302 sofia/internal/1001@35.185.177.49:5060 sending invite version: 1.8.5 -6-31281a0bf1 64bit
Local SDP:
v=0
o=FreeSWITCH 1557543124 1557543125 IN IP4 14.161.40.203
s=FreeSWITCH
c=IN IP4 14.161.40.203
t=0 0
m=audio 24356 RTP/AVP 0 9 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
m=video 16410 RTP/AVP 102 103
b=AS:1024
a=rtpmap:102 H264/90000
a=rtpmap:103 VP8/90000
a=sendrecv
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 ccm tmmbr
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli
a=rtcp-fb:103 ccm fir
a=rtcp-fb:103 ccm tmmbr
a=rtcp-fb:103 nack
a=rtcp-fb:103 nack pli

2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@35.185.177.49:5060 Standard INIT
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@35.185.177.49:5060) State Change CS_INIT -> CS_ROUTING
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@35.185.177.49:5060) State INIT going to sleep
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@35.185.177.49:5060) Running State Change CS_ROUTING (Cur 2 Tot 15)
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@35.185.177.49:5060) State ROUTING
2019-05-11 16:38:00.097264 [DEBUG] mod_sofia.c:154 sofia/internal/1001@35.185.177.49:5060 SOFIA ROUTING
2019-05-11 16:38:00.097264 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@35.185.177.49:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@35.185.177.49:5060) State ROUTING going to sleep
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@35.185.177.49:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 15)
2019-05-11 16:38:00.097264 [DEBUG] sofia.c:7291 Channel sofia/internal/1001@35.185.177.49:5060 entering state [calling][0]
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@35.185.177.49:5060) State CONSUME_MEDIA
2019-05-11 16:38:00.097264 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@35.185.177.49:5060) State CONSUME_MEDIA going to sleep
2019-05-11 16:38:00.097264 [DEBUG] switch_ivr_async.c:1614 No silence detection configured; assuming start of speech
2019-05-11 16:38:00.877309 [DEBUG] sofia.c:7291 Channel sofia/internal/1001@35.185.177.49:5060 entering state [proceeding][180]
2019-05-11 16:38:00.877309 [NOTICE] sofia.c:7401 Ring-Ready sofia/internal/1001@35.185.177.49:5060!
2019-05-11 16:38:00.877309 [DEBUG] switch_channel.c:3354 (sofia/internal/1001@35.185.177.49:5060) Callstate Change DOWN -> RINGING
2019-05-11 16:38:00.917299 [DEBUG] switch_ivr_originate.c:1304 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2019-05-11 16:38:00.917299 [DEBUG] switch_core_codec.c:223 sofia/internal/0906366151@113.164.240.242 Push codec L16:100
2019-05-11 16:38:00.917299 [DEBUG] switch_ivr_originate.c:1373 Play Ringback Tone [%(2000,4000,440,480)]
2019-05-11 16:38:01.237309 [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 80
2019-05-11 16:38:04.697307 [DEBUG] sofia.c:7291 Channel sofia/internal/1001@35.185.177.49:5060 entering state [proceeding][180]
2019-05-11 16:38:04.717296 [NOTICE] sofia.c:1079 Hangup sofia/internal/0906366151@113.164.240.242 [CS_EXECUTE] [NORMAL_CLEARING]
2019-05-11 16:38:04.717296 [DEBUG] mod_hash.c:297 Usage for sip.vietvan.net_1001 is now 0
2019-05-11 16:38:04.717296 [DEBUG] switch_core_codec.c:248 sofia/internal/0906366151@113.164.240.242 Restore previous codec PCMU:0.
2019-05-11 16:38:04.717296 [NOTICE] switch_ivr_originate.c:3705 Hangup sofia/internal/1001@35.185.177.49:5060 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
2019-05-11 16:38:04.717296 [DEBUG] switch_ivr_originate.c:3930 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@35.185.177.49:5060) Running State Change CS_HANGUP (Cur 2 Tot 15)
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/1001@35.185.177.49:5060) Callstate Change RINGING -> HANGUP
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1001@35.185.177.49:5060) State HANGUP
2019-05-11 16:38:04.717296 [DEBUG] mod_sofia.c:443 sofia/internal/1001@35.185.177.49:5060 Overriding SIP cause 487 with 200 from the other leg
2019-05-11 16:38:04.717296 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1001@35.185.177.49:5060 hanging up, cause: ORIGINATOR_CANCEL
2019-05-11 16:38:04.717296 [NOTICE] switch_ivr_originate.c:2944 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
2019-05-11 16:38:04.717296 [DEBUG] switch_ivr_originate.c:3941 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2019-05-11 16:38:04.717296 [DEBUG] mod_sofia.c:514 Sending CANCEL to sofia/internal/1001@35.185.177.49:5060
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@35.185.177.49:5060 Standard HANGUP, cause: ORIGINATOR_CANCEL
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1001@35.185.177.49:5060) State HANGUP going to sleep
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@35.185.177.49:5060) State Change CS_HANGUP -> CS_REPORTING
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@35.185.177.49:5060) Running State Change CS_REPORTING (Cur 2 Tot 15)
2019-05-11 16:38:04.717296 [INFO] mod_dptools.c:3518 Originate Failed. Cause: ORIGINATOR_CANCEL
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1001@35.185.177.49:5060) State REPORTING
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@35.185.177.49:5060 Standard REPORTING, cause: ORIGINATOR_CANCEL
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1001@35.185.177.49:5060) State REPORTING going to sleep
2019-05-11 16:38:04.717296 [DEBUG] switch_core_session.c:2887 sofia/internal/0906366151@113.164.240.242 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/0906366151@113.164.240.242) State EXECUTE going to sleep
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_HANGUP (Cur 2 Tot 15)
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@35.185.177.49:5060) State Change CS_REPORTING -> CS_DESTROY
2019-05-11 16:38:04.717296 [DEBUG] switch_core_session.c:1715 Session 15 (sofia/internal/1001@35.185.177.49:5060) Locked, Waiting on external entities
2019-05-11 16:38:04.717296 [DEBUG] switch_core_media_bug.c:1276 Removing BUG from sofia/internal/0906366151@113.164.240.242
2019-05-11 16:38:04.717296 [DEBUG] switch_ivr_async.c:1419 Stop recording file /var/lib/freeswitch/recordings/sip.vietvan.net/archive/2019/May/11/756464c8-2671-4808-bde3-ef8fc5ab2064.wav
2019-05-11 16:38:04.717296 [NOTICE] switch_core_session.c:1733 Session 15 (sofia/internal/1001@35.185.177.49:5060) Ended
2019-05-11 16:38:04.717296 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/1001@35.185.177.49:5060 [CS_DESTROY]
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/1001@35.185.177.49:5060) Running State Change CS_DESTROY (Cur 1 Tot 15)
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1001@35.185.177.49:5060) State DESTROY
2019-05-11 16:38:04.717296 [DEBUG] mod_sofia.c:354 sofia/internal/1001@35.185.177.49:5060 SOFIA DESTROY
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@35.185.177.49:5060 Standard DESTROY
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1001@35.185.177.49:5060) State DESTROY going to sleep
2019-05-11 16:38:04.717296 [DEBUG] switch_ivr_async.c:1494 Channel is hung up
2019-05-11 16:38:04.717296 [DEBUG] switch_core_media_bug.c:1276 Removing BUG from sofia/internal/0906366151@113.164.240.242
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/0906366151@113.164.240.242) Callstate Change RING_WAIT -> HANGUP
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/0906366151@113.164.240.242) State HANGUP
2019-05-11 16:38:04.717296 [DEBUG] mod_sofia.c:449 Channel sofia/internal/0906366151@113.164.240.242 hanging up, cause: NORMAL_CLEARING
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:60 sofia/internal/0906366151@113.164.240.242 Standard HANGUP, cause: NORMAL_CLEARING
2019-05-11 16:38:04.717296 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/0906366151@113.164.240.242) State HANGUP going to sleep
2019-05-11 16:38:09.077291 [DEBUG] switch_utils.c:1212 Emailed data to [quangleehong@gmail.com]
2019-05-11 16:38:09.077291 [DEBUG] switch_core_state_machine.c:780 Hangup Command with no Session lua(app.lua hangup):

2019-05-11 16:38:09.077291 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/0906366151@113.164.240.242) State Change CS_HANGUP -> CS_REPORTING
2019-05-11 16:38:09.077291 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_REPORTING (Cur 1 Tot 15)
2019-05-11 16:38:09.077291 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/0906366151@113.164.240.242) State REPORTING
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:174 sofia/internal/0906366151@113.164.240.242 Standard REPORTING, cause: NORMAL_CLEARING
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/0906366151@113.164.240.242) State REPORTING going to sleep
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/0906366151@113.164.240.242) State Change CS_REPORTING -> CS_DESTROY
2019-05-11 16:38:09.117263 [DEBUG] switch_core_session.c:1715 Session 14 (sofia/internal/0906366151@113.164.240.242) Locked, Waiting on external entities
2019-05-11 16:38:09.117263 [NOTICE] switch_core_session.c:1733 Session 14 (sofia/internal/0906366151@113.164.240.242) Ended
2019-05-11 16:38:09.117263 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/0906366151@113.164.240.242 [CS_DESTROY]
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/0906366151@113.164.240.242) Running State Change CS_DESTROY (Cur 0 Tot 15)
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/0906366151@113.164.240.242) State DESTROY
2019-05-11 16:38:09.117263 [DEBUG] mod_sofia.c:354 sofia/internal/0906366151@113.164.240.242 SOFIA DESTROY
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:181 sofia/internal/0906366151@113.164.240.242 Standard DESTROY
2019-05-11 16:38:09.117263 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/0906366151@113.164.240.242) State DESTROY going to sleep.
 
i just modified a bit the regex of incoming DID matching the pattern as follow then i do not see the 1st failed attempt. all is good now
the regex pattern:


<extension name="842877766698" continue="false" uuid="0e953987-01a0-4f0d-ab33-dc82d9292080">
<condition field="destination_number" expression="^(842877766698)|^(02877766698)$">
<action application="export" data="call_direction=inbound" inline="true"/>
<action application="set" data="domain_uuid=c1ca509a-ef4e-4934-acc2-c9f06d77c60b" inline="true"/>
<action application="set" data="domain_name=domain_name_here" inline="true"/>
<action application="set" data="hangup_after_bridge=true"/>
<action application="set" data="continue_on_fail=true"/>
<action application="set" data="tone_detect_hits=1"/>
<action application="set" data="execute_on_tone_detect=transfer 7000 XML ${domain_name}"/>
<action application="tone_detect" data="fax 1100 r +5000"/>
<action application="answer" data=""/>
<action application="sleep" data="3000"/>
<action application="transfer" data="extension_munber XML sip.vietvan.net"/>
</condition>
</extension>


I think my SIP provider will always insert the country_code in the incoming DID for e.164 rule, but the other local operators just send area_code + number only to local calls

BUT i just don't know why without modify the regex of incoming DID, i can still get the inbound call for the 2nd attempt