Step by step inbound multi-tenant

Massimiliano Iavazzo · Feb 9, 2018

Hello to everyone,

I'm really new to this forum, more newbie to freeswitch and fusionpbx. Since now, I have always used Asterisk, FreePBX, and all tolls you surely just know.

I'm decided to move to fusionpbx to use multi-tenant feature to use a single machine to give separated PBX features to my customers. Actually I use a separated FreePBX for each one.

I have used Ubuntu 8, and successfully installed FusionPBX 4.2. I have created 1 domain more than default one, created a superadmin user for new domain, added extensions, registered a 3cx software, added a gateway to a myself billing external server, and created an outbound route.

Where I locked is in inbound, because I have created a destination with a DID number routed to a single extension, but I receive always a forbidden freeswitch error message and I don't know how resolve:

2018-02-09 02:52:28.977109 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/39xxxxxxxxxxxx@188.165.219.229) State NEW
2018-02-09 02:52:28.997093 [DEBUG] sofia.c:2442 Re-attaching to session ec062a91-c480-4848-a7cf-e4349397c360
2018-02-09 02:52:29.017106 [DEBUG] sofia.c:9873 sofia/internal/39xxxxxxxxx@188.165.219.229 receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-09 02:52:29.017106 [DEBUG] sofia.c:10044 IP 188.xxx.xxx.xxx Rejected by acl "domains". Falling back to Digest auth.
2018-02-09 02:52:29.037091 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f44b4183b00 Connected.
2018-02-09 02:52:29.037091 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f44b4183b00 released.
2018-02-09 02:52:29.037091 [WARNING] sofia_reg.c:2906 Can't find user [1319@149.xxx.xxx.xxx] from 188.xxx.xxx.xxx
You must define a domain called '149.xxx.xxx.xxx' in your directory and add a user with the id="1319" attribute
and you must configure your device to use the proper domain in it's authentication credentials.
2018-02-09 02:52:29.037091 [NOTICE] sofia.c:2332 Hangup sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [CS_NEW] [CALL_REJECTED]
2018-02-09 02:52:29.037091 [WARNING] sofia_reg.c:1737 SIP auth failure (INVITE) on sofia profile 'internal' for [gw+e2fc27aa-9423-4d7b-91c1-7144e9196b00@149.202.48.43] from ip 188.xxx.xxx.xxx

I hope someone could firstly explain what I wrong, and how it works for incoming route, then help to resolve.

Thank you.

DigitalDaz · Feb 10, 2018

You need to be sending the inbound did numbers to port 5080

If you cannot do this you need to add your carrier to the domains ACL in advanced access control.

Massimiliano Iavazzo · Feb 10, 2018

I have added the provider IP into ACL with /32 prefix and it works

Massimiliano Iavazzo · Feb 13, 2018

Another problem. I have different DID providers.

One provider put the country prefix in front of number and I successfully receive call on 3cx connected to Fusion
Other provider remove country prefix and sent number starting with 0 and I receive always CALL REJECTED

it could be that the dropping cause ?

DigitalDaz · Feb 13, 2018

Absolutely, you need to configure each destination to suit the provider.

Massimiliano Iavazzo · Feb 13, 2018

I have configured both inbound DIDs but while in first case I receive call and I can see that:

2018-02-13 10:12:07.628343 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefd40ca980 Connected.
2018-02-13 10:12:07.628343 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefd40ca980 released.
2018-02-13 10:15:22.028342 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [e7744be8-a577-4dad-9b31-6dd90f81d638]
2018-02-13 10:15:22.028342 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 117)
2018-02-13 10:15:22.028342 [DEBUG] sofia.c:9873 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-13 10:15:22.028342 [DEBUG] sofia.c:9989 IP 188.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2018-02-13 10:15:22.028342 [DEBUG] sofia.c:7084 Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx entering state [received][100]
2018-02-13 10:15:22.028342 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 574577930 574577930 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 19144 RTP/AVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

in the other case I can see following:

2018-02-13 10:19:04.788345 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [f32135e7-3231-4e4c-8d40-323f0802592d]
2018-02-13 10:19:04.788345 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 119)
2018-02-13 10:19:04.788345 [DEBUG] sofia.c:9873 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-13 10:19:04.788345 [DEBUG] sofia.c:9989 IP 188.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2018-02-13 10:19:04.788345 [DEBUG] sofia.c:7084 Channel sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx entering state [received][100]
2018-02-13 10:19:04.788345 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 227570801 227570801 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 10402 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
.........
2018-02-13 10:19:05.008337 [NOTICE] sofia.c:8273 Hangup sofia/internal/100 [CS_CONSUME_MEDIA] [CALL_REJECTED]
.......
2018-02-13 10:19:05.008337 [INFO] mod_dptools.c:3436 Originate Failed. Cause: CALL_REJECTED
2018-02-13 10:19:05.008337 [NOTICE] switch_core_state_machine.c:385 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx has executed the last dialplan instruction, hanging up.
2018-02-13 10:19:05.008337 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]

Any hints ?

DigitalDaz · Feb 13, 2018

No, paste a full log

Massimiliano Iavazzo · Feb 13, 2018

of failed call ?

Massimiliano Iavazzo · Feb 13, 2018

This is the log of FAILED call:

[This app Best viewed at 160x60 or more..]
+OK log level [7]
2018-02-13 10:35:26.068356 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'internal' for [100@pbx.xxxxxxxxxxxxx.com] from ip 5.158.67.106
2018-02-13 10:35:26.528343 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'internal' for [100@pbx.xxxxxxxxxxxxx.com] from ip 5.158.67.106
2018-02-13 10:35:37.328335 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [0cc536d0-b71e-402f-b5c0-97c9a46f59a3]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 121)
2018-02-13 10:35:37.328335 [DEBUG] sofia.c:9873 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-13 10:35:37.328335 [DEBUG] sofia.c:9989 IP 188.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2018-02-13 10:35:37.328335 [DEBUG] sofia.c:7084 Channel sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx entering state [received][100]
2018-02-13 10:35:37.328335 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 728764212 728764212 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 10036 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2018-02-13 10:35:37.328335 [DEBUG] switch_core_codec.c:111 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Original read codec set to PCMA:8
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-02-13 10:35:37.328335 [DEBUG] switch_core_media.c:4767 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Set 2833 dtmf send payload to 101 recv payload to 101
2018-02-13 10:35:37.328335 [DEBUG] sofia.c:7507 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_NEW -> CS_INIT
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State NEW
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_INIT (Cur 1 Tot 121)
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State INIT
2018-02-13 10:35:37.328335 [DEBUG] mod_sofia.c:90 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx SOFIA INIT
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:40 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard INIT
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_INIT -> CS_ROUTING
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State INIT going to sleep
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 121)
2018-02-13 10:35:37.328335 [DEBUG] switch_channel.c:2249 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change DOWN -> RINGING
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 10:35:37.328335 [DEBUG] mod_sofia.c:143 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 10:35:37.328335 [DEBUG] switch_core_state_machine.c:236 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 10:35:37.328335 [INFO] mod_dialplan_xml.c:637 Processing xxxxxxxxxx <xxxxxxxxxx>->1619 in context public
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->08119034166] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [08119034166] destination_number(1619) =~ /^(08119034166)$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1319] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319] destination_number(1619) =~ /^(1319)$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1619] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1619] destination_number(1619) =~ /^(1619)$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=inbound)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[inbound]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_uuid=9f28c57f-5bb1-4b77-9540-170aaf3655aa) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(domain_uuid=9f28c57f-5bb1-4b77-9540-170aaf3655aa)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [domain_uuid]=[9f28c57f-5bb1-4b77-9540-170aaf3655aa]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_name=pbx.xxxxxxxxxxxxx.com) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(domain_name=pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [domain_name]=[pbx.xxxxxxxxxxxxx.com]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(source=39${source})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_number=39${caller_id_number})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action transfer(100 XML pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 121)
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 10:35:37.348344 [DEBUG] mod_sofia.c:198 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:328 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(source=39mod_sofia)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [source]=[39mod_sofia]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_number=39xxxxxxxxxx)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_number]=[39xxxxxxxxxx]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx transfer(100 XML pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:35:37.348344 [DEBUG] switch_ivr.c:2165 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_EXECUTE -> CS_ROUTING
2018-02-13 10:35:37.348344 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx to XML[100@pbx.xxxxxxxxxxxxx.com]
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 121)
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 10:35:37.348344 [DEBUG] mod_sofia.c:143 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 10:35:37.348344 [DEBUG] switch_core_state_machine.c:236 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 10:35:37.348344 [INFO] mod_dialplan_xml.c:637 Processing xxxxxxxxxx <xxxxxxxxxx>->100 in context pbx.xxxxxxxxxxxxx.com
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->user_exists] continue=true
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(user_exists=true)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [user_exists]=[true]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(extension_uuid=121c9bc6-d594-4fcc-b3cc-dcba7ca028df)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [extension_uuid]=[121c9bc6-d594-4fcc-b3cc-dcba7ca028df]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(hold_music=local_stream://default)
2018-02-13 10:35:37.348344 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [hold_music]=[local_stream://default]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_enabled=false)
2018-02-13 10:35:37.368335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_enabled]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_destination=)
2018-02-13 10:35:37.368335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_enabled=false)
2018-02-13 10:35:37.368335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_enabled]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_destination=)
2018-02-13 10:35:37.368335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_enabled=false)
2018-02-13 10:35:37.368335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_enabled]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_destination=)
2018-02-13 10:35:37.368335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_enabled=false)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_enabled]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_destination=)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(do_not_disturb=false)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [do_not_disturb]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(call_timeout=30)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [call_timeout]=[30]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_app=)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_data=)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(toll_allow=)
2018-02-13 10:35:37.388342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [toll_allow]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(call_screen_enabled=false)
2018-02-13 10:35:37.408336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [call_screen_enabled]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call-direction] continue=true
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->variables] continue=true
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->user_record] continue=true
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(user_record=)
2018-02-13 10:35:37.408336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [user_record]=[UNDEF]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2018-02-13 10:35:37.488334 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefc0090610 Connected.
2018-02-13 10:35:37.488334 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefc0090610 released.
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(from_user_exists=false)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [from_user_exists]=[false]
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->redial] continue=true
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [redial] destination_number(100) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->speed_dial] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [speed_dial] destination_number(100) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1619.10d] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.10d] destination_number(100) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1619.11d] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.11d] destination_number(100) =~ /^\+?(\d{11})$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1619.8d] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.8d] destination_number(100) =~ /^(\d{8})$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1619.9d] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.9d] destination_number(100) =~ /^(\d{9})$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1619.d3] continue=false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1619.d3] destination_number(100) =~ /^(\d{3})$/ break=on-false
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=outbound)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action unset(call_timeout)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(inherit_codec=true)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(ignore_display_updates=true)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(callee_id_number=100)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action set(continue_on_fail=true)
Dialplan: sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Action bridge(sofia/gateway/1d9c1c6c-14d9-45b5-a020-512905541a56/100)
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 121)
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 10:35:37.488334 [DEBUG] mod_sofia.c:198 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:328 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx export(origination_callee_id_name=100)
2018-02-13 10:35:37.488334 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[100]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(RFC2822_DATE=Tue, 13 Feb 2018 10:35:37 +0100)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [RFC2822_DATE]=[Tue, 13 Feb 2018 10:35:37 +0100]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxx.com-last_dial/xxxxxxxxxx/100)
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(sip_h_X-accountcode=)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [sip_h_X-accountcode]=[UNDEF]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=outbound)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[outbound]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx unset(call_timeout)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(hangup_after_bridge=true)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [hangup_after_bridge]=[true]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_name=)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_number=)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_number]=[UNDEF]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(inherit_codec=true)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [inherit_codec]=[true]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(ignore_display_updates=true)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [ignore_display_updates]=[true]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(callee_id_number=100)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [callee_id_number]=[100]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx set(continue_on_fail=true)
2018-02-13 10:35:37.488334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [continue_on_fail]=[true]
EXECUTE sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx bridge(sofia/gateway/1d9c1c6c-14d9-45b5-a020-512905541a56/100)
2018-02-13 10:35:37.488334 [DEBUG] switch_channel.c:1250 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [origination_callee_id_name]=[100] to event
2018-02-13 10:35:37.488334 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-13 10:35:37.488334 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/100 [e627382d-2322-4eba-af6a-3fd43f80c1de]
2018-02-13 10:35:37.488334 [DEBUG] mod_sofia.c:4819 (sofia/internal/100) State Change CS_NEW -> CS_INIT
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_INIT (Cur 2 Tot 122)
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100) State INIT
2018-02-13 10:35:37.488334 [DEBUG] mod_sofia.c:90 sofia/internal/100 SOFIA INIT
2018-02-13 10:35:37.488334 [DEBUG] sofia_glue.c:1295 sofia/internal/100 sending invite version: 1.6.20 -37-987c9b9 64bit
Local SDP:
v=0
o=FreeSWITCH 1518497037 1518497038 IN IP4 149.202.48.43
s=FreeSWITCH
c=IN IP4 149.202.48.43
t=0 0
m=audio 17500 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100 Standard INIT
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100) State Change CS_INIT -> CS_ROUTING
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100) State INIT going to sleep
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_ROUTING (Cur 2 Tot 122)
2018-02-13 10:35:37.488334 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [calling][0]
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100) State ROUTING
2018-02-13 10:35:37.488334 [DEBUG] mod_sofia.c:143 sofia/internal/100 SOFIA ROUTING
2018-02-13 10:35:37.488334 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/100) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100) State ROUTING going to sleep
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 122)
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/100) State CONSUME_MEDIA
2018-02-13 10:35:37.488334 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/100) State CONSUME_MEDIA going to sleep
2018-02-13 10:35:37.508335 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [calling][0]
2018-02-13 10:35:37.548333 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [terminated][403]
2018-02-13 10:35:37.548333 [NOTICE] sofia.c:8273 Hangup sofia/internal/100 [CS_CONSUME_MEDIA] [CALL_REJECTED]
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_HANGUP (Cur 2 Tot 122)
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100) Callstate Change DOWN -> HANGUP
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100) State HANGUP
2018-02-13 10:35:37.548333 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100 hanging up, cause: CALL_REJECTED
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100 Standard HANGUP, cause: CALL_REJECTED
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100) State HANGUP going to sleep
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_REPORTING (Cur 2 Tot 122)
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100) State REPORTING
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100 Standard REPORTING, cause: CALL_REJECTED
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100) State REPORTING going to sleep
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 10:35:37.548333 [DEBUG] switch_core_session.c:1665 Session 122 (sofia/internal/100) Locked, Waiting on external entities
2018-02-13 10:35:37.548333 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 21 [CALL_REJECTED]
2018-02-13 10:35:37.548333 [INFO] mod_dptools.c:3436 Originate Failed. Cause: CALL_REJECTED
2018-02-13 10:35:37.548333 [NOTICE] switch_core_state_machine.c:385 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx has executed the last dialplan instruction, hanging up.
2018-02-13 10:35:37.548333 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_HANGUP (Cur 2 Tot 122)
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change RINGING -> HANGUP
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP
2018-02-13 10:35:37.548333 [DEBUG] mod_sofia.c:432 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Overriding SIP cause 480 with 403 from the other leg
2018-02-13 10:35:37.548333 [DEBUG] mod_sofia.c:438 Channel sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx hanging up, cause: NORMAL_CLEARING
2018-02-13 10:35:37.548333 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 403
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:60 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard HANGUP, cause: NORMAL_CLEARING
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP going to sleep
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_REPORTING (Cur 2 Tot 122)
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING
2018-02-13 10:35:37.548333 [NOTICE] switch_core_session.c:1683 Session 122 (sofia/internal/100) Ended
2018-02-13 10:35:37.548333 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/100 [CS_DESTROY]
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100) Running State Change CS_DESTROY (Cur 1 Tot 122)
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100) State DESTROY
2018-02-13 10:35:37.548333 [DEBUG] mod_sofia.c:343 sofia/internal/100 SOFIA DESTROY
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100 Standard DESTROY
2018-02-13 10:35:37.548333 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100) State DESTROY going to sleep
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:174 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard REPORTING, cause: NORMAL_CLEARING
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING going to sleep
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 10:35:37.688344 [DEBUG] switch_core_session.c:1665 Session 121 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Locked, Waiting on external entities
2018-02-13 10:35:37.688344 [NOTICE] switch_core_session.c:1683 Session 121 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Ended
2018-02-13 10:35:37.688344 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx [CS_DESTROY]
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_DESTROY (Cur 0 Tot 122)
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY
2018-02-13 10:35:37.688344 [DEBUG] mod_sofia.c:343 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx SOFIA DESTROY
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:181 sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx Standard DESTROY
2018-02-13 10:35:37.688344 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY going to sleep
freeswitch@vps423280.ovh.net> /bye

Massimiliano Iavazzo · Feb 13, 2018

Instead this is the CALL LOG of a GOOD call:

+OK log level [7]
2018-02-13 10:44:51.368368 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'internal' for [10@pbx.xxxxxxxxxxxxx.com] from ip 5.158.67.106
2018-02-13 10:45:56.668378 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [a806128b-3df7-44e2-9b5d-27e34eadd4c9]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 123)
2018-02-13 10:45:56.668378 [DEBUG] sofia.c:9873 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-13 10:45:56.668378 [DEBUG] sofia.c:9989 IP 188.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2018-02-13 10:45:56.668378 [DEBUG] sofia.c:7084 Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx entering state [received][100]
2018-02-13 10:45:56.668378 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 465065100 465065100 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 13392 RTP/AVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2018-02-13 10:45:56.668378 [DEBUG] switch_core_codec.c:111 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Original read codec set to PCMU:0
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-02-13 10:45:56.668378 [DEBUG] switch_core_media.c:4767 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Set 2833 dtmf send payload to 101 recv payload to 101
2018-02-13 10:45:56.668378 [DEBUG] sofia.c:7507 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_NEW -> CS_INIT
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State NEW
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_INIT (Cur 1 Tot 123)
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State INIT
2018-02-13 10:45:56.668378 [DEBUG] mod_sofia.c:90 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx SOFIA INIT
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:40 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard INIT
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_INIT -> CS_ROUTING
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State INIT going to sleep
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 123)
2018-02-13 10:45:56.668378 [DEBUG] switch_channel.c:2249 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change DOWN -> RINGING
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 10:45:56.668378 [DEBUG] mod_sofia.c:143 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:236 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 10:45:56.668378 [INFO] mod_dialplan_xml.c:637 Processing Massimiliano Iavazzo <39xxxxxxxxxx>->1319 in context public
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->08119034166] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [08119034166] destination_number(1319) =~ /^(08119034166)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1319] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1319] destination_number(1319) =~ /^(1319)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=inbound)
2018-02-13 10:45:56.668378 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[inbound]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_uuid=c0124463-9738-4ef9-a3b6-b83f3c9a2dd1) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(domain_uuid=c0124463-9738-4ef9-a3b6-b83f3c9a2dd1)
2018-02-13 10:45:56.668378 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [domain_uuid]=[c0124463-9738-4ef9-a3b6-b83f3c9a2dd1]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_name=pbx.xxxxxxxxxxxxx.com) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(domain_name=pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:45:56.668378 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [domain_name]=[pbx.xxxxxxxxxxxxx.com]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action transfer(10 XML pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 123)
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 10:45:56.668378 [DEBUG] mod_sofia.c:198 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:328 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx transfer(10 XML pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:45:56.668378 [DEBUG] switch_ivr.c:2165 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_EXECUTE -> CS_ROUTING
2018-02-13 10:45:56.668378 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx to XML[10@pbx.xxxxxxxxxxxxx.com]
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 123)
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 10:45:56.668378 [DEBUG] mod_sofia.c:143 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 10:45:56.668378 [DEBUG] switch_core_state_machine.c:236 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 10:45:56.668378 [INFO] mod_dialplan_xml.c:637 Processing Massimiliano Iavazzo <39xxxxxxxxxx>->10 in context pbx.xxxxxxxxxxxxx.com
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->user_exists] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(user_exists=true)
2018-02-13 10:45:56.708349 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [user_exists]=[true]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(extension_uuid=3854c483-2814-4dc3-b53f-b70a9bf23a3f)
2018-02-13 10:45:56.708349 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [extension_uuid]=[3854c483-2814-4dc3-b53f-b70a9bf23a3f]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(hold_music=local_stream://default)
2018-02-13 10:45:56.708349 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [hold_music]=[local_stream://default]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_enabled=)
2018-02-13 10:45:56.728342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_destination=)
2018-02-13 10:45:56.728342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_enabled=)
2018-02-13 10:45:56.728342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_enabled]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_destination=)
2018-02-13 10:45:56.728342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_enabled=)
2018-02-13 10:45:56.728342 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_enabled]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_destination=)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_enabled=)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_enabled]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_destination=)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(do_not_disturb=)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [do_not_disturb]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(call_timeout=30)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [call_timeout]=[30]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_app=)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_data=)
2018-02-13 10:45:56.748337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(toll_allow=)
2018-02-13 10:45:56.768336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [toll_allow]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(call_screen_enabled=false)
2018-02-13 10:45:56.768336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [call_screen_enabled]=[false]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call-direction] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->variables] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->user_record] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(user_record=)
2018-02-13 10:45:56.768336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [user_record]=[UNDEF]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2018-02-13 10:45:56.828333 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefc009a4a0 Connected.
2018-02-13 10:45:56.828333 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefc009a4a0 released.
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(from_user_exists=false)
2018-02-13 10:45:56.828333 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [from_user_exists]=[false]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->redial] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [redial] destination_number(10) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->speed_dial] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [speed_dial] destination_number(10) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1319.10d] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319.10d] destination_number(10) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1319.11d] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319.11d] destination_number(10) =~ /^\+?(\d{11})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1319.8d] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319.8d] destination_number(10) =~ /^(\d{8})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1319.9d] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319.9d] destination_number(10) =~ /^(\d{9})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->1319.d6] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319.d6] destination_number(10) =~ /^(\d{6})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->agent_status] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [agent_status] destination_number(10) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->agent_status_id] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [agent_status_id] destination_number(10) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->group-intercept] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [group-intercept] destination_number(10) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->page-extension] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [page-extension] destination_number(10) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->eavesdrop] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [eavesdrop] destination_number(10) =~ /^\*33(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call_privacy] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call_privacy] destination_number(10) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call_return] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call_return] destination_number(10) =~ /^\*69$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->extension_queue] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [extension_queue] destination_number(10) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->intercept-ext] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [intercept-ext] destination_number(10) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [intercept-ext-polycom] destination_number(10) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->dx] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [dx] destination_number(10) =~ /^dx$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->att_xfer] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [att_xfer] destination_number(10) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->extension-to-voicemail] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [extension-to-voicemail] username(39xxxxxxxxxx) =~ /^39xxxxxxxxxx$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [extension-to-voicemail] destination_number(10) =~ /^39xxxxxxxxxx$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->send_to_voicemail] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [send_to_voicemail] destination_number(10) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->vmain] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [vmain] destination_number(10) =~ /^vmain$|^\*4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->xfer_vm] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [xfer_vm] destination_number(10) =~ /^xfer_vm$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->is_transfer] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [is_transfer] destination_number(10) =~ /^is_transfer$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->vmain_user] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [vmain_user] destination_number(10) =~ /^\*97$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->cf] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [cf] destination_number(10) =~ /^cf$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->delay_echo] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [delay_echo] destination_number(10) =~ /^\*9195$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->echo] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [echo] destination_number(10) =~ /^\*9196$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->is_zrtp_secure] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx ANTI-Action eval(not_secure)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->milliwatt] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [milliwatt] destination_number(10) =~ /^\*9197$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->is_secure] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->tone_stream] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [tone_stream] destination_number(10) =~ /^\*9198$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->hold_music] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [hold_music] destination_number(10) =~ /^\*9664$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->recordings] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [recordings] destination_number(10) =~ /^\*(732)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->directory] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [directory] destination_number(10) =~ /^\*411$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->wake-up] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [wake-up] destination_number(10) =~ /^\*(925)$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->valet_park] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [valet_park] destination_number(10) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip

.*)@.*/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [valet_park] destination_number(10) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [valet_park] destination_number(10) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->operator] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [operator] destination_number(10) =~ /^0$|^operator$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->operator-forward] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [operator-forward] destination_number(10) =~ /^\*000$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->do-not-disturb] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [do-not-disturb] destination_number(10) =~ /^\*77$/ break=on-true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [do-not-disturb] destination_number(10) =~ /^\*78$|\*363$/ break=on-true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [do-not-disturb] destination_number(10) =~ /^\*79$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call-forward] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call-forward] destination_number(10) =~ /^\*72$/ break=on-true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call-forward] destination_number(10) =~ /^\*73$/ break=on-true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call-forward] destination_number(10) =~ /^\*74$/ break=on-true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call forward all] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [call forward all] ${user_exists}(true) =~ /^true/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call forward all] ${forward_all_enabled}() =~ /^true/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->follow-me] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [follow-me] destination_number(10) =~ /^\*21$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->talking clock date and time] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [talking clock date and time] destination_number(10) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->talking clock time] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [talking clock time] destination_number(10) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->talking clock date] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [talking clock date] destination_number(10) =~ /^\*9171$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->call_screen] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->local_extension] continue=true
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action export(dialed_extension=${destination_number}) INLINE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx export(dialed_extension=10)
2018-02-13 10:45:56.828333 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[10]
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [local_extension] () =~ // break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(continue_on_fail=true)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(api_hangup_hook=lua app.lua hangup)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action export(domain_name=${domain_name})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action bridge(user/${destination_number}@${domain_name})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action lua(app.lua failure_handler)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxx.com->voicemail] continue=false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action answer()
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action sleep(1000)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(voicemail_action=save)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(voicemail_id=${destination_number})
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action set(voicemail_profile=default)
Dialplan: sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Action lua(app.lua voicemail)
2018-02-13 10:45:56.828333 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 10:45:56.828333 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 10:45:56.828333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 123)
2018-02-13 10:45:56.828333 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 10:45:56.828333 [DEBUG] mod_sofia.c:198 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 10:45:56.828333 [DEBUG] switch_core_state_machine.c:328 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx export(origination_callee_id_name=10)
2018-02-13 10:45:56.828333 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[10]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(RFC2822_DATE=Tue, 13 Feb 2018 10:45:56 +0100)
2018-02-13 10:45:56.828333 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [RFC2822_DATE]=[Tue, 13 Feb 2018 10:45:56 +0100]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxx.com-last_dial/39xxxxxxxxxx/10)
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx eval(not_secure)
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx limit(hash pbx.xxxxxxxxxxxxx.com 10 )
2018-02-13 10:45:56.828333 [DEBUG] switch_limit.c:126 incr called: pbx.xxxxxxxxxxxxx.com_10 max:-1, interval:0
2018-02-13 10:45:56.828333 [DEBUG] mod_hash.c:194 Usage for pbx.xxxxxxxxxxxxx.com_10 is now 1
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(hangup_after_bridge=true)
2018-02-13 10:45:56.828333 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [hangup_after_bridge]=[true]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(continue_on_fail=true)
2018-02-13 10:45:56.828333 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [continue_on_fail]=[true]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxx.com-call_return/10/39xxxxxxxxxx)
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxx.com-last_dial_ext/10/a806128b-3df7-44e2-9b5d-27e34eadd4c9)
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(called_party_call_group=)
2018-02-13 10:45:56.848334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [called_party_call_group]=[UNDEF]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxx.com-last_dial//a806128b-3df7-44e2-9b5d-27e34eadd4c9)
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx set(api_hangup_hook=lua app.lua hangup)
2018-02-13 10:45:56.848334 [DEBUG] mod_dptools.c:1548 SET sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [api_hangup_hook]=[lua app.lua hangup]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx export(domain_name=pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=[pbx.xxxxxxxxxxxxx.com]
EXECUTE sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx bridge(user/10@pbx.xxxxxxxxxxxxx.com)
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1250 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [dialed_extension]=[10] to event
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1250 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [origination_callee_id_name]=[10] to event
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1250 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [domain_name]=[pbx.xxxxxxxxxxxxx.com] to event
2018-02-13 10:45:56.848334 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1250 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [dialed_extension]=[10] to event
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1250 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [origination_callee_id_name]=[10] to event
2018-02-13 10:45:56.848334 [DEBUG] switch_channel.c:1250 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [domain_name]=[pbx.xxxxxxxxxxxxx.com] to event
2018-02-13 10:45:56.848334 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-13 10:45:56.848334 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/10@192.168.178.28:63537 [f903097f-3bde-4f68-855f-15f5077b9622]
2018-02-13 10:45:56.848334 [DEBUG] mod_sofia.c:4819 (sofia/internal/10@192.168.178.28:63537) State Change CS_NEW -> CS_INIT
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@192.168.178.28:63537) Running State Change CS_INIT (Cur 2 Tot 124)
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@192.168.178.28:63537) State INIT
2018-02-13 10:45:56.848334 [DEBUG] mod_sofia.c:90 sofia/internal/10@192.168.178.28:63537 SOFIA INIT
2018-02-13 10:45:56.848334 [DEBUG] sofia_glue.c:1264 sip:10@5.158.67.106:63537;rinstance=3c41b67dddc8d533 Setting proxy route to sofia/internal/10@192.168.178.28:63537
2018-02-13 10:45:56.848334 [DEBUG] sofia_glue.c:1295 sofia/internal/10@192.168.178.28:63537 sending invite version: 1.6.20 -37-987c9b9 64bit
Local SDP:
v=0
o=FreeSWITCH 1518491846 1518491847 IN IP4 149.202.48.43
s=FreeSWITCH
c=IN IP4 149.202.48.43
t=0 0
m=audio 23310 RTP/AVP 0 9 8 3 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:40 sofia/internal/10@192.168.178.28:63537 Standard INIT
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/10@192.168.178.28:63537) State Change CS_INIT -> CS_ROUTING
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/10@192.168.178.28:63537) State INIT going to sleep
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@192.168.178.28:63537) Running State Change CS_ROUTING (Cur 2 Tot 124)
2018-02-13 10:45:56.848334 [DEBUG] sofia.c:7084 Channel sofia/internal/10@192.168.178.28:63537 entering state [calling][0]
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@192.168.178.28:63537) State ROUTING
2018-02-13 10:45:56.848334 [DEBUG] mod_sofia.c:143 sofia/internal/10@192.168.178.28:63537 SOFIA ROUTING
2018-02-13 10:45:56.848334 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/10@192.168.178.28:63537) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/10@192.168.178.28:63537) State ROUTING going to sleep
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@192.168.178.28:63537) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 124)
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@192.168.178.28:63537) State CONSUME_MEDIA
2018-02-13 10:45:56.848334 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10@192.168.178.28:63537) State CONSUME_MEDIA going to sleep
2018-02-13 10:45:57.048358 [DEBUG] sofia.c:7084 Channel sofia/internal/10@192.168.178.28:63537 entering state [proceeding][180]
2018-02-13 10:45:57.048358 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/10@192.168.178.28:63537!
2018-02-13 10:45:57.048358 [DEBUG] switch_channel.c:3346 (sofia/internal/10@192.168.178.28:63537) Callstate Change DOWN -> RINGING
2018-02-13 10:45:57.048358 [INFO] switch_ivr_originate.c:1215 Sending early media
2018-02-13 10:45:57.048358 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx] 149.202.48.43 port 22898 -> 188.xxx.xxx.xxx port 13392 codec: 0 ms: 20
2018-02-13 10:45:57.048358 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
2018-02-13 10:45:57.048358 [DEBUG] switch_core_media.c:7180 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Set 2833 dtmf send payload to 101
2018-02-13 10:45:57.048358 [DEBUG] switch_core_media.c:7187 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Set 2833 dtmf receive payload to 101
2018-02-13 10:45:57.048358 [DEBUG] switch_core_media.c:7210 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Set rtp dtmf delay to 40
2018-02-13 10:45:57.048358 [DEBUG] mod_sofia.c:2364 Ring SDP:
v=0
o=FreeSWITCH 1518492259 1518492260 IN IP4 149.202.48.43
s=FreeSWITCH
c=IN IP4 149.202.48.43
t=0 0
m=audio 22898 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2018-02-13 10:45:57.048358 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx!
2018-02-13 10:45:57.048358 [DEBUG] switch_channel.c:3474 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change RINGING -> EARLY
2018-02-13 10:45:57.048358 [DEBUG] sofia.c:7084 Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx entering state [early][183]
2018-02-13 10:45:57.048358 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2018-02-13 10:45:57.048358 [DEBUG] switch_core_codec.c:223 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Push codec L16:100
2018-02-13 10:45:57.048358 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)]
2018-02-13 10:45:57.288344 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2018-02-13 10:46:01.628342 [DEBUG] sofia.c:7084 Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx entering state [terminated][487]
2018-02-13 10:46:01.628342 [NOTICE] sofia.c:8273 Hangup sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [CS_EXECUTE] [ORIGINATOR_CANCEL]
2018-02-13 10:46:01.628342 [DEBUG] mod_hash.c:297 Usage for pbx.xxxxxxxxxxxxx.com_10 is now 0
2018-02-13 10:46:01.628342 [DEBUG] switch_core_codec.c:248 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Restore previous codec PCMU:0.
2018-02-13 10:46:01.628342 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/internal/10@192.168.178.28:63537 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
2018-02-13 10:46:01.628342 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
2018-02-13 10:46:01.628342 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
2018-02-13 10:46:01.628342 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2018-02-13 10:46:01.628342 [INFO] mod_dptools.c:3436 Originate Failed. Cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.628342 [DEBUG] switch_core_session.c:2815 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_HANGUP (Cur 2 Tot 124)
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change EARLY -> HANGUP
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP
2018-02-13 10:46:01.628342 [DEBUG] mod_sofia.c:438 Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx hanging up, cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:60 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard HANGUP, cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP going to sleep
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:783 Hangup Command with no Session lua(app.lua hangup):

2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_REPORTING (Cur 2 Tot 124)
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@192.168.178.28:63537) Running State Change CS_HANGUP (Cur 2 Tot 124)
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/10@192.168.178.28:63537) Callstate Change RINGING -> HANGUP
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@192.168.178.28:63537) State HANGUP
2018-02-13 10:46:01.628342 [DEBUG] mod_sofia.c:432 sofia/internal/10@192.168.178.28:63537 Overriding SIP cause 487 with 487 from the other leg
2018-02-13 10:46:01.628342 [DEBUG] mod_sofia.c:438 Channel sofia/internal/10@192.168.178.28:63537 hanging up, cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.628342 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/10@192.168.178.28:63537
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:60 sofia/internal/10@192.168.178.28:63537 Standard HANGUP, cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10@192.168.178.28:63537) State HANGUP going to sleep
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/10@192.168.178.28:63537) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10@192.168.178.28:63537) Running State Change CS_REPORTING (Cur 2 Tot 124)
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@192.168.178.28:63537) State REPORTING
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:174 sofia/internal/10@192.168.178.28:63537 Standard REPORTING, cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10@192.168.178.28:63537) State REPORTING going to sleep
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/10@192.168.178.28:63537) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 10:46:01.628342 [DEBUG] switch_core_session.c:1665 Session 124 (sofia/internal/10@192.168.178.28:63537) Locked, Waiting on external entities
2018-02-13 10:46:01.628342 [NOTICE] switch_core_session.c:1683 Session 124 (sofia/internal/10@192.168.178.28:63537) Ended
2018-02-13 10:46:01.628342 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/10@192.168.178.28:63537 [CS_DESTROY]
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/10@192.168.178.28:63537) Running State Change CS_DESTROY (Cur 1 Tot 124)
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@192.168.178.28:63537) State DESTROY
2018-02-13 10:46:01.628342 [DEBUG] mod_sofia.c:343 sofia/internal/10@192.168.178.28:63537 SOFIA DESTROY
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:181 sofia/internal/10@192.168.178.28:63537 Standard DESTROY
2018-02-13 10:46:01.628342 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10@192.168.178.28:63537) State DESTROY going to sleep
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:174 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard REPORTING, cause: ORIGINATOR_CANCEL
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING going to sleep
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 10:46:01.708340 [DEBUG] switch_core_session.c:1665 Session 123 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Locked, Waiting on external entities
2018-02-13 10:46:01.708340 [NOTICE] switch_core_session.c:1683 Session 123 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Ended
2018-02-13 10:46:01.708340 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx [CS_DESTROY]
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_DESTROY (Cur 0 Tot 124)
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY
2018-02-13 10:46:01.708340 [DEBUG] mod_sofia.c:343 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx SOFIA DESTROY
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:181 sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx Standard DESTROY
2018-02-13 10:46:01.708340 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/39xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY going to sleep
freeswitch@vps423280.ovh.net> /bye

DigitalDaz · Feb 13, 2018

There is nothing wrong with the inbound route it is routing the call to extension 100

Massimiliano Iavazzo · Feb 13, 2018

I have seen.

I don't change anything and I'm using 3cx for both extensions (10 and 100). The only different thing is used domain.

As you have seen, the only thing I captured of different on log is the international prefix on received callerid for good call and no international prefix on failed call , but I don't thing it could be that the problem. Or not ?

How can I troubleshoot ?

DigitalDaz · Feb 13, 2018

You really want to turn on sip capture and see what is being sent to and from the phone.

sofia global siptrace on

Massimiliano Iavazzo · Feb 13, 2018

freeswitch@vpsXXXXXX.ovh.net> sofia global siptrace on
+OK Global siptrace on
recv 1118 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.447849:
------------------------------------------------------------------------
INVITE sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3 SIP/2.0
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK6cd3b867;rport
Max-Forwards: 70
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as35644109
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>
Contact: <sip:3xxxxxxxxxx@188.xxx.xxx.xxx:5060>
Call-ID: 154e5165590d75707aae9f386b9dac14@188.xxx.xxx.xxx:5060
CSeq: 102 INVITE
User-Agent: MOR Softswitch
Date: Tue, 13 Feb 2018 14:56:20 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 314

v=0
o=root 1572885576 1572885576 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 12512 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
send 374 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.448329:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK6cd3b867;rport=5060
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as35644109
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>
Call-ID: 154e5165590d75707aae9f386b9dac14@188.xxx.xxx.xxx:5060
CSeq: 102 INVITE
User-Agent: FreeSWITCH
Content-Length: 0

------------------------------------------------------------------------
2018-02-13 15:56:19.508364 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [7c07ccea-1f62-4e57-b94b-4e5d0b62a8a7]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 131)
2018-02-13 15:56:19.508364 [DEBUG] sofia.c:9873 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-13 15:56:19.508364 [DEBUG] sofia.c:9989 IP 188.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2018-02-13 15:56:19.508364 [DEBUG] sofia.c:7084 Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx entering state [received][100]
2018-02-13 15:56:19.508364 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 1572885576 1572885576 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 12512 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2018-02-13 15:56:19.508364 [DEBUG] switch_core_codec.c:111 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Original read codec set to PCMA:8
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-02-13 15:56:19.508364 [DEBUG] switch_core_media.c:4767 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Set 2833 dtmf send payload to 101 recv payload to 101
2018-02-13 15:56:19.508364 [DEBUG] sofia.c:7507 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_NEW -> CS_INIT
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State NEW
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_INIT (Cur 1 Tot 131)
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State INIT
2018-02-13 15:56:19.508364 [DEBUG] mod_sofia.c:90 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA INIT
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:40 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard INIT
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_INIT -> CS_ROUTING
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State INIT going to sleep
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 131)
2018-02-13 15:56:19.508364 [DEBUG] switch_channel.c:2249 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change DOWN -> RINGING
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 15:56:19.508364 [DEBUG] mod_sofia.c:143 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 15:56:19.508364 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 15:56:19.508364 [INFO] mod_dialplan_xml.c:637 Processing 3xxxxxxxxxx <3xxxxxxxxxx>->1619 in context public
2018-02-13 15:56:19.608334 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefd40def90 Connected.
2018-02-13 15:56:19.628335 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefd40def90 released.
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1319] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319] destination_number(1619) =~ /^(1319)$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1619] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1619] destination_number(1619) =~ /^(1619)$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=inbound)
2018-02-13 15:56:19.628335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[inbound]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_uuid=9f28c57f-5bb1-4b77-9540-170aaf3655aa) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(domain_uuid=9f28c57f-5bb1-4b77-9540-170aaf3655aa)
2018-02-13 15:56:19.628335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [domain_uuid]=[9f28c57f-5bb1-4b77-9540-170aaf3655aa]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_name=pbx.xxxxxxxxxxxxxxxxxxx.com) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(domain_name=pbx.xxxxxxxxxxxxxxxxxxx.com)
2018-02-13 15:56:19.628335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [domain_name]=[pbx.xxxxxxxxxxxxxxxxxxx.com]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action transfer(100 XML pbx.xxxxxxxxxxxxxxxxxxx.com)
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 131)
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 15:56:19.628335 [DEBUG] mod_sofia.c:198 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx transfer(100 XML pbx.xxxxxxxxxxxxxxxxxxx.com)
2018-02-13 15:56:19.628335 [DEBUG] switch_ivr.c:2165 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_EXECUTE -> CS_ROUTING
2018-02-13 15:56:19.628335 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx to XML[100@pbx.xxxxxxxxxxxxxxxxxxx.com]
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 131)
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 15:56:19.628335 [DEBUG] mod_sofia.c:143 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 15:56:19.628335 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 15:56:19.628335 [INFO] mod_dialplan_xml.c:637 Processing 3xxxxxxxxxx <3xxxxxxxxxx>->100 in context pbx.xxxxxxxxxxxxxxxxxxx.com
2018-02-13 15:56:19.628335 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefd40def90 Connected.
2018-02-13 15:56:19.668338 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefd40def90 released.
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->user_exists] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(user_exists=true)
2018-02-13 15:56:19.668338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [user_exists]=[true]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(extension_uuid=121c9bc6-d594-4fcc-b3cc-dcba7ca028df)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [extension_uuid]=[121c9bc6-d594-4fcc-b3cc-dcba7ca028df]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(hold_music=local_stream://default)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [hold_music]=[local_stream://default]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_enabled=false)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_destination=)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_enabled=false)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_destination=)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_enabled=false)
2018-02-13 15:56:19.688336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_destination=)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_enabled=false)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_destination=)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(do_not_disturb=false)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [do_not_disturb]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_timeout=30)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_timeout]=[30]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_app=)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_data=)
2018-02-13 15:56:19.708335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(toll_allow=)
2018-02-13 15:56:19.728335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [toll_allow]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_screen_enabled=false)
2018-02-13 15:56:19.728335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_screen_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->call-direction] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->variables] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->user_record] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(user_record=)
2018-02-13 15:56:19.728335 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [user_record]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2018-02-13 15:56:19.728335 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefd40def90 Connected.
2018-02-13 15:56:19.748336 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefd40def90 released.
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(from_user_exists=false)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [from_user_exists]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->redial] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [redial] destination_number(100) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->speed_dial] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [speed_dial] destination_number(100) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.10d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.10d] destination_number(100) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.11d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.11d] destination_number(100) =~ /^\+?(\d{11})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.8d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.8d] destination_number(100) =~ /^(\d{8})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.9d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.9d] destination_number(100) =~ /^(\d{9})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.d3] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1619.d3] destination_number(100) =~ /^(\d{3})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=outbound)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action unset(call_timeout)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(inherit_codec=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(ignore_display_updates=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(callee_id_number=100)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(continue_on_fail=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action bridge(sofia/gateway/1d9c1c6c-14d9-45b5-a020-512905541a56/100)
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 131)
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 15:56:19.748336 [DEBUG] mod_sofia.c:198 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx export(origination_callee_id_name=100)
2018-02-13 15:56:19.748336 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[100]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(RFC2822_DATE=Tue, 13 Feb 2018 15:56:19 +0100)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [RFC2822_DATE]=[Tue, 13 Feb 2018 15:56:19 +0100]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxxxxxxxx.com-last_dial/3xxxxxxxxxx/100)
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(sip_h_X-accountcode=)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [sip_h_X-accountcode]=[UNDEF]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=outbound)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[outbound]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx unset(call_timeout)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(hangup_after_bridge=true)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [hangup_after_bridge]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_name=)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_number=)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_number]=[UNDEF]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(inherit_codec=true)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [inherit_codec]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(ignore_display_updates=true)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [ignore_display_updates]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(callee_id_number=100)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [callee_id_number]=[100]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(continue_on_fail=true)
2018-02-13 15:56:19.748336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [continue_on_fail]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx bridge(sofia/gateway/1d9c1c6c-14d9-45b5-a020-512905541a56/100)
2018-02-13 15:56:19.748336 [DEBUG] switch_channel.c:1250 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [origination_callee_id_name]=[100] to event
2018-02-13 15:56:19.748336 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-13 15:56:19.748336 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/100 [1ea5a29c-d15c-4d29-b846-c529e2e421ae]
2018-02-13 15:56:19.748336 [DEBUG] mod_sofia.c:4819 (sofia/internal/100) State Change CS_NEW -> CS_INIT
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_INIT (Cur 2 Tot 132)
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100) State INIT
2018-02-13 15:56:19.748336 [DEBUG] mod_sofia.c:90 sofia/internal/100 SOFIA INIT
2018-02-13 15:56:19.748336 [DEBUG] sofia_glue.c:1295 sofia/internal/100 sending invite version: 1.6.20 -37-987c9b9 64bit
Local SDP:
v=0
o=FreeSWITCH 1518516963 1518516964 IN IP4 149.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 149.xxx.xxx.xxx
t=0 0
m=audio 16816 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100 Standard INIT
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100) State Change CS_INIT -> CS_ROUTING
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100) State INIT going to sleep
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_ROUTING (Cur 2 Tot 132)
2018-02-13 15:56:19.748336 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [calling][0]
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100) State ROUTING
2018-02-13 15:56:19.748336 [DEBUG] mod_sofia.c:143 sofia/internal/100 SOFIA ROUTING
2018-02-13 15:56:19.748336 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/100) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100) State ROUTING going to sleep
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 132)
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/100) State CONSUME_MEDIA
2018-02-13 15:56:19.748336 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/100) State CONSUME_MEDIA going to sleep
send 1348 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.677871:
------------------------------------------------------------------------
INVITE sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK3gg89p5ZZHjDa
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930826 INVITE
Contact: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp;gw=1d9c1c6c-14d9-45b5-a020-512905541a56>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 317
X-FS-Support: update_display,send_info
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@voip.connecting-peoples.com>;party=calling;screen=no;privacy=off

v=0
o=FreeSWITCH 1518516963 1518516964 IN IP4 149.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 149.xxx.xxx.xxx
t=0 0
m=audio 16816 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
recv 567 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.687480:
------------------------------------------------------------------------
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;branch=z9hG4bK3gg89p5ZZHjDa;received=149.xxx.xxx.xxx;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>;tag=as455f4232
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930826 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6191915c"
Content-Length: 0

------------------------------------------------------------------------
send 357 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.687584:
------------------------------------------------------------------------
ACK sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK3gg89p5ZZHjDa
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>;tag=as455f4232
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930826 ACK
Content-Length: 0

------------------------------------------------------------------------
send 1526 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.687861:
------------------------------------------------------------------------
INVITE sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK4S90Bjp3vt8ZN
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 INVITE
Contact: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp;gw=1d9c1c6c-14d9-45b5-a020-512905541a56>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Authorization: Digest username="1619", realm="asterisk", nonce="6191915c", algorithm=MD5, uri="sip:100@voip.connecting-peoples.com", response="6648637e018730f37df4dbc742e8cded"
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 317
X-FS-Support: update_display,send_info
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@voip.connecting-peoples.com>;party=calling;screen=no;privacy=off

v=0
o=FreeSWITCH 1518516963 1518516964 IN IP4 149.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 149.xxx.xxx.xxx
t=0 0
m=audio 16816 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
2018-02-13 15:56:19.768330 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [calling][0]
recv 548 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.699951:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;branch=z9hG4bK4S90Bjp3vt8ZN;received=149.xxx.xxx.xxx;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:100@188.xxx.xxx.xxx:5060>
Content-Length: 0

------------------------------------------------------------------------
recv 525 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.726811:
------------------------------------------------------------------------
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;branch=z9hG4bK4S90Bjp3vt8ZN;received=149.xxx.xxx.xxx;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>;tag=as425a0481
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0

------------------------------------------------------------------------
send 357 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.726923:
------------------------------------------------------------------------
ACK sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK4S90Bjp3vt8ZN
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>;tag=as425a0481
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 ACK
Content-Length: 0

------------------------------------------------------------------------
2018-02-13 15:56:19.808331 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [terminated][403]
2018-02-13 15:56:19.808331 [NOTICE] sofia.c:8273 Hangup sofia/internal/100 [CS_CONSUME_MEDIA] [CALL_REJECTED]
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_HANGUP (Cur 2 Tot 132)
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100) Callstate Change DOWN -> HANGUP
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100) State HANGUP
2018-02-13 15:56:19.808331 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100 hanging up, cause: CALL_REJECTED
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100 Standard HANGUP, cause: CALL_REJECTED
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100) State HANGUP going to sleep
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_REPORTING (Cur 2 Tot 132)
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100) State REPORTING
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100 Standard REPORTING, cause: CALL_REJECTED
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100) State REPORTING going to sleep
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 15:56:19.808331 [DEBUG] switch_core_session.c:1665 Session 132 (sofia/internal/100) Locked, Waiting on external entities
2018-02-13 15:56:19.808331 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 21 [CALL_REJECTED]
2018-02-13 15:56:19.808331 [INFO] mod_dptools.c:3436 Originate Failed. Cause: CALL_REJECTED
2018-02-13 15:56:19.808331 [NOTICE] switch_core_state_machine.c:385 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx has executed the last dialplan instruction, hanging up.
2018-02-13 15:56:19.808331 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_HANGUP (Cur 2 Tot 132)
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change RINGING -> HANGUP
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP
2018-02-13 15:56:19.808331 [DEBUG] mod_sofia.c:432 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Overriding SIP cause 480 with 403 from the other leg
2018-02-13 15:56:19.808331 [DEBUG] mod_sofia.c:438 Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx hanging up, cause: NORMAL_CLEARING
2018-02-13 15:56:19.808331 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 403
send 884 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.729372:
------------------------------------------------------------------------
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK6cd3b867;rport=5060
Max-Forwards: 69
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as35644109
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>;tag=m87ay7mQmcmBB
Call-ID: 154e5165590d75707aae9f386b9dac14@188.xxx.xxx.xxx:5060
CSeq: 102 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
Remote-Party-ID: "100" <sip:100@149.xxx.xxx.xxx>;party=calling;privacy=off;screen=no

------------------------------------------------------------------------
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:60 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard HANGUP, cause: NORMAL_CLEARING
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP going to sleep
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_REPORTING (Cur 2 Tot 132)
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING
2018-02-13 15:56:19.808331 [NOTICE] switch_core_session.c:1683 Session 132 (sofia/internal/100) Ended
2018-02-13 15:56:19.808331 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/100 [CS_DESTROY]
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100) Running State Change CS_DESTROY (Cur 1 Tot 132)
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100) State DESTROY
2018-02-13 15:56:19.808331 [DEBUG] mod_sofia.c:343 sofia/internal/100 SOFIA DESTROY
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100 Standard DESTROY
2018-02-13 15:56:19.808331 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100) State DESTROY going to sleep
recv 524 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.740017:
------------------------------------------------------------------------
ACK sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK6cd3b867;rport
Max-Forwards: 70
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as35644109
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>;tag=m87ay7mQmcmBB
Contact: <sip:3xxxxxxxxxx@188.xxx.xxx.xxx:5060>
Call-ID: 154e5165590d75707aae9f386b9dac14@188.xxx.xxx.xxx:5060
CSeq: 102 ACK
User-Agent: MOR Softswitch
Content-Length: 0

------------------------------------------------------------------------
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:174 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard REPORTING, cause: NORMAL_CLEARING
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING going to sleep
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 15:56:19.928336 [DEBUG] switch_core_session.c:1665 Session 131 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Locked, Waiting on external entities
2018-02-13 15:56:19.928336 [NOTICE] switch_core_session.c:1683 Session 131 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Ended
2018-02-13 15:56:19.928336 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [CS_DESTROY]
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_DESTROY (Cur 0 Tot 132)
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY
2018-02-13 15:56:19.928336 [DEBUG] mod_sofia.c:343 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA DESTROY
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:181 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard DESTROY
2018-02-13 15:56:19.928336 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY going to sleep
recv 1118 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.004518:
------------------------------------------------------------------------
INVITE sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3 SIP/2.0
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK0a9a98ac;rport
Max-Forwards: 70
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as76cb24eb
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>
Contact: <sip:3xxxxxxxxxx@188.xxx.xxx.xxx:5060>
Call-ID: 4351efb011df5b0e1db26b363e931d2c@188.xxx.xxx.xxx:5060
CSeq: 102 INVITE
User-Agent: MOR Softswitch
Date: Tue, 13 Feb 2018 14:56:21 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 314

v=0
o=root 1272098580 1272098580 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 10906 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
send 374 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.004804:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK0a9a98ac;rport=5060
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as76cb24eb
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>
Call-ID: 4351efb011df5b0e1db26b363e931d2c@188.xxx.xxx.xxx:5060
CSeq: 102 INVITE
User-Agent: FreeSWITCH
Content-Length: 0

------------------------------------------------------------------------
2018-02-13 15:56:21.088349 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [34e9a018-3464-489d-81b2-d0aefa2f9020]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_NEW (Cur 1 Tot 133)
2018-02-13 15:56:21.088349 [DEBUG] sofia.c:9873 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx receiving invite from 188.xxx.xxx.xxx:5060 version: 1.6.20 -37-987c9b9 64bit
2018-02-13 15:56:21.088349 [DEBUG] sofia.c:9989 IP 188.xxx.xxx.xxx Approved by acl "domains[]". Access Granted.
2018-02-13 15:56:21.088349 [DEBUG] sofia.c:7084 Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx entering state [received][100]
2018-02-13 15:56:21.088349 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 1272098580 1272098580 IN IP4 188.xxx.xxx.xxx
s=Asterisk PBX 1.8.32.3
c=IN IP4 188.xxx.xxx.xxx
t=0 0
m=audio 10906 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2018-02-13 15:56:21.088349 [DEBUG] switch_core_codec.c:111 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Original read codec set to PCMA:8
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2018-02-13 15:56:21.088349 [DEBUG] switch_core_media.c:4767 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Set 2833 dtmf send payload to 101 recv payload to 101
2018-02-13 15:56:21.088349 [DEBUG] sofia.c:7507 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_NEW -> CS_INIT
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State NEW
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_INIT (Cur 1 Tot 133)
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State INIT
2018-02-13 15:56:21.088349 [DEBUG] mod_sofia.c:90 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA INIT
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:40 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard INIT
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_INIT -> CS_ROUTING
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State INIT going to sleep
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 133)
2018-02-13 15:56:21.088349 [DEBUG] switch_channel.c:2249 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change DOWN -> RINGING
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 15:56:21.088349 [DEBUG] mod_sofia.c:143 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 15:56:21.088349 [INFO] mod_dialplan_xml.c:637 Processing 3xxxxxxxxxx <3xxxxxxxxxx>->1619 in context public
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1319] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1319] destination_number(1619) =~ /^(1319)$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [public->1619] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1619] destination_number(1619) =~ /^(1619)$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=inbound)
2018-02-13 15:56:21.088349 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[inbound]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_uuid=9f28c57f-5bb1-4b77-9540-170aaf3655aa) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(domain_uuid=9f28c57f-5bb1-4b77-9540-170aaf3655aa)
2018-02-13 15:56:21.088349 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [domain_uuid]=[9f28c57f-5bb1-4b77-9540-170aaf3655aa]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(domain_name=pbx.xxxxxxxxxxxxxxxxxxx.com) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(domain_name=pbx.xxxxxxxxxxxxxxxxxxx.com)
2018-02-13 15:56:21.088349 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [domain_name]=[pbx.xxxxxxxxxxxxxxxxxxx.com]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action transfer(100 XML pbx.xxxxxxxxxxxxxxxxxxx.com)
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 15:56:21.088349 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 133)
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 15:56:21.108339 [DEBUG] mod_sofia.c:198 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx transfer(100 XML pbx.xxxxxxxxxxxxxxxxxxx.com)
2018-02-13 15:56:21.108339 [DEBUG] switch_ivr.c:2165 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_EXECUTE -> CS_ROUTING
2018-02-13 15:56:21.108339 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx to XML[100@pbx.xxxxxxxxxxxxxxxxxxx.com]
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_ROUTING (Cur 1 Tot 133)
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING
2018-02-13 15:56:21.108339 [DEBUG] mod_sofia.c:143 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA ROUTING
2018-02-13 15:56:21.108339 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard ROUTING
2018-02-13 15:56:21.108339 [INFO] mod_dialplan_xml.c:637 Processing 3xxxxxxxxxx <3xxxxxxxxxx>->100 in context pbx.xxxxxxxxxxxxxxxxxxx.com
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->user_exists] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(user_exists=true)
2018-02-13 15:56:21.108339 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [user_exists]=[true]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(extension_uuid=121c9bc6-d594-4fcc-b3cc-dcba7ca028df)
2018-02-13 15:56:21.108339 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [extension_uuid]=[121c9bc6-d594-4fcc-b3cc-dcba7ca028df]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(hold_music=local_stream://default)
2018-02-13 15:56:21.128341 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [hold_music]=[local_stream://default]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_enabled=false)
2018-02-13 15:56:21.128341 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_all_destination=)
2018-02-13 15:56:21.128341 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_enabled=false)
2018-02-13 15:56:21.128341 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_busy_destination=)
2018-02-13 15:56:21.128341 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_enabled=false)
2018-02-13 15:56:21.148338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_no_answer_destination=)
2018-02-13 15:56:21.148338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_enabled=false)
2018-02-13 15:56:21.148338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(forward_user_not_registered_destination=)
2018-02-13 15:56:21.148338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(do_not_disturb=false)
2018-02-13 15:56:21.148338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [do_not_disturb]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_timeout=30)
2018-02-13 15:56:21.148338 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_timeout]=[30]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_app=)
2018-02-13 15:56:21.168337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(missed_call_data=)
2018-02-13 15:56:21.168337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(toll_allow=)
2018-02-13 15:56:21.168337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [toll_allow]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_screen_enabled=false)
2018-02-13 15:56:21.168337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_screen_enabled]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->call-direction] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->variables] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->user_record] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(user_record=)
2018-02-13 15:56:21.168337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [user_record]=[UNDEF]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2018-02-13 15:56:21.168337 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fefd40def90 Connected.
2018-02-13 15:56:21.168337 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fefd40def90 released.
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(from_user_exists=false)
2018-02-13 15:56:21.168337 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [from_user_exists]=[false]
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->redial] continue=true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [redial] destination_number(100) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->speed_dial] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [speed_dial] destination_number(100) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.10d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.10d] destination_number(100) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.11d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.11d] destination_number(100) =~ /^\+?(\d{11})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.8d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.8d] destination_number(100) =~ /^(\d{8})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.9d] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (FAIL) [1619.9d] destination_number(100) =~ /^(\d{9})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx parsing [pbx.xxxxxxxxxxxxxxxxxxx.com->1619.d3] continue=false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Regex (PASS) [1619.d3] destination_number(100) =~ /^(\d{3})$/ break=on-false
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(call_direction=outbound)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action unset(call_timeout)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(inherit_codec=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(ignore_display_updates=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(callee_id_number=100)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action set(continue_on_fail=true)
Dialplan: sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Action bridge(sofia/gateway/1d9c1c6c-14d9-45b5-a020-512905541a56/100)
2018-02-13 15:56:21.168337 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_ROUTING -> CS_EXECUTE
2018-02-13 15:56:21.168337 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State ROUTING going to sleep
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_EXECUTE (Cur 1 Tot 133)
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE
2018-02-13 15:56:21.188336 [DEBUG] mod_sofia.c:198 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA EXECUTE
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard EXECUTE
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx export(origination_callee_id_name=100)
2018-02-13 15:56:21.188336 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[100]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(RFC2822_DATE=Tue, 13 Feb 2018 15:56:21 +0100)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [RFC2822_DATE]=[Tue, 13 Feb 2018 15:56:21 +0100]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx hash(insert/pbx.xxxxxxxxxxxxxxxxxxx.com-last_dial/3xxxxxxxxxx/100)
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(sip_h_X-accountcode=)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [sip_h_X-accountcode]=[UNDEF]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(call_direction=outbound)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [call_direction]=[outbound]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx unset(call_timeout)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(hangup_after_bridge=true)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [hangup_after_bridge]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_name=)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(effective_caller_id_number=)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [effective_caller_id_number]=[UNDEF]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(inherit_codec=true)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [inherit_codec]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(ignore_display_updates=true)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [ignore_display_updates]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(callee_id_number=100)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [callee_id_number]=[100]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx set(continue_on_fail=true)
2018-02-13 15:56:21.188336 [DEBUG] mod_dptools.c:1548 SET sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [continue_on_fail]=[true]
EXECUTE sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx bridge(sofia/gateway/1d9c1c6c-14d9-45b5-a020-512905541a56/100)
2018-02-13 15:56:21.188336 [DEBUG] switch_channel.c:1250 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx EXPORTING[export_vars] [origination_callee_id_name]=[100] to event
2018-02-13 15:56:21.188336 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-13 15:56:21.188336 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/100 [91a69f18-468c-402b-8fbd-40a8787c5131]
2018-02-13 15:56:21.188336 [DEBUG] mod_sofia.c:4819 (sofia/internal/100) State Change CS_NEW -> CS_INIT
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_INIT (Cur 2 Tot 134)
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100) State INIT
2018-02-13 15:56:21.188336 [DEBUG] mod_sofia.c:90 sofia/internal/100 SOFIA INIT
2018-02-13 15:56:21.188336 [DEBUG] sofia_glue.c:1295 sofia/internal/100 sending invite version: 1.6.20 -37-987c9b9 64bit
Local SDP:
v=0
o=FreeSWITCH 1518512457 1518512458 IN IP4 149.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 149.xxx.xxx.xxx
t=0 0
m=audio 21324 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

send 1348 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.097449:
------------------------------------------------------------------------
INVITE sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK522SDD76S3yjH
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 INVITE
Contact: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp;gw=1d9c1c6c-14d9-45b5-a020-512905541a56>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 317
X-FS-Support: update_display,send_info
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@voip.connecting-peoples.com>;party=calling;screen=no;privacy=off

v=0
o=FreeSWITCH 1518512457 1518512458 IN IP4 149.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 149.xxx.xxx.xxx
t=0 0
m=audio 21324 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100 Standard INIT
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100) State Change CS_INIT -> CS_ROUTING
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100) State INIT going to sleep
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_ROUTING (Cur 2 Tot 134)
2018-02-13 15:56:21.188336 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [calling][0]
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100) State ROUTING
2018-02-13 15:56:21.188336 [DEBUG] mod_sofia.c:143 sofia/internal/100 SOFIA ROUTING
2018-02-13 15:56:21.188336 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/100) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100) State ROUTING going to sleep
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 134)
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/100) State CONSUME_MEDIA
2018-02-13 15:56:21.188336 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/100) State CONSUME_MEDIA going to sleep
recv 567 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.106997:
------------------------------------------------------------------------
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;branch=z9hG4bK522SDD76S3yjH;received=149.xxx.xxx.xxx;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>;tag=as31f1ad98
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="347d8ae8"
Content-Length: 0

------------------------------------------------------------------------
send 357 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.107072:
------------------------------------------------------------------------
ACK sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK522SDD76S3yjH
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>;tag=as31f1ad98
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930827 ACK
Content-Length: 0

------------------------------------------------------------------------
send 1526 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.107292:
------------------------------------------------------------------------
INVITE sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK6BvjF8QaQcN5c
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930828 INVITE
Contact: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp;gw=1d9c1c6c-14d9-45b5-a020-512905541a56>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Authorization: Digest username="1619", realm="asterisk", nonce="347d8ae8", algorithm=MD5, uri="sip:100@voip.connecting-peoples.com", response="26bad2591c2279333b76ffb40ab4043c"
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 317
X-FS-Support: update_display,send_info
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@voip.connecting-peoples.com>;party=calling;screen=no;privacy=off

v=0
o=FreeSWITCH 1518512457 1518512458 IN IP4 149.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 149.xxx.xxx.xxx
t=0 0
m=audio 21324 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
2018-02-13 15:56:21.188336 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [calling][0]
recv 548 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.117491:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;branch=z9hG4bK6BvjF8QaQcN5c;received=149.xxx.xxx.xxx;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930828 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:100@188.xxx.xxx.xxx:5060>
Content-Length: 0

------------------------------------------------------------------------
recv 525 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.137928:
------------------------------------------------------------------------
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;branch=z9hG4bK6BvjF8QaQcN5c;received=149.xxx.xxx.xxx;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>;tag=as469ff0ce
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930828 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0

------------------------------------------------------------------------
send 357 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.138002:
------------------------------------------------------------------------
ACK sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.xxx.xxx.xxx;rport;branch=z9hG4bK6BvjF8QaQcN5c
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=Q3KN3r71B7p3D
To: <sip:100@voip.connecting-peoples.com>;tag=as469ff0ce
Call-ID: e57c8a35-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930828 ACK
Content-Length: 0

------------------------------------------------------------------------
2018-02-13 15:56:21.228331 [DEBUG] sofia.c:7084 Channel sofia/internal/100 entering state [terminated][403]
2018-02-13 15:56:21.228331 [NOTICE] sofia.c:8273 Hangup sofia/internal/100 [CS_CONSUME_MEDIA] [CALL_REJECTED]
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_HANGUP (Cur 2 Tot 134)
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100) Callstate Change DOWN -> HANGUP
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100) State HANGUP
2018-02-13 15:56:21.228331 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100 hanging up, cause: CALL_REJECTED
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100 Standard HANGUP, cause: CALL_REJECTED
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100) State HANGUP going to sleep
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100) Running State Change CS_REPORTING (Cur 2 Tot 134)
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100) State REPORTING
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100 Standard REPORTING, cause: CALL_REJECTED
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100) State REPORTING going to sleep
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 15:56:21.228331 [DEBUG] switch_core_session.c:1665 Session 134 (sofia/internal/100) Locked, Waiting on external entities
2018-02-13 15:56:21.228331 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 21 [CALL_REJECTED]
2018-02-13 15:56:21.228331 [INFO] mod_dptools.c:3436 Originate Failed. Cause: CALL_REJECTED
2018-02-13 15:56:21.228331 [NOTICE] switch_core_state_machine.c:385 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx has executed the last dialplan instruction, hanging up.
2018-02-13 15:56:21.228331 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State EXECUTE going to sleep
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_HANGUP (Cur 2 Tot 134)
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Callstate Change RINGING -> HANGUP
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP
2018-02-13 15:56:21.228331 [DEBUG] mod_sofia.c:432 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Overriding SIP cause 480 with 403 from the other leg
2018-02-13 15:56:21.228331 [DEBUG] mod_sofia.c:438 Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx hanging up, cause: NORMAL_CLEARING
2018-02-13 15:56:21.228331 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 403
send 884 bytes to udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.139973:
------------------------------------------------------------------------
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK0a9a98ac;rport=5060
Max-Forwards: 69
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as76cb24eb
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>;tag=pttv1Xpyey0gj
Call-ID: 4351efb011df5b0e1db26b363e931d2c@188.xxx.xxx.xxx:5060
CSeq: 102 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
Remote-Party-ID: "100" <sip:100@149.xxx.xxx.xxx>;party=calling;privacy=off;screen=no

------------------------------------------------------------------------
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:60 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard HANGUP, cause: NORMAL_CLEARING
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State HANGUP going to sleep
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_HANGUP -> CS_REPORTING
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_REPORTING (Cur 2 Tot 134)
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING
2018-02-13 15:56:21.228331 [NOTICE] switch_core_session.c:1683 Session 134 (sofia/internal/100) Ended
2018-02-13 15:56:21.228331 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/100 [CS_DESTROY]
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100) Running State Change CS_DESTROY (Cur 1 Tot 134)
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100) State DESTROY
2018-02-13 15:56:21.228331 [DEBUG] mod_sofia.c:343 sofia/internal/100 SOFIA DESTROY
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100 Standard DESTROY
2018-02-13 15:56:21.228331 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100) State DESTROY going to sleep
recv 524 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:22.149328:
------------------------------------------------------------------------
ACK sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 188.xxx.xxx.xxx:5060;branch=z9hG4bK0a9a98ac;rport
Max-Forwards: 70
From: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@188.xxx.xxx.xxx>;tag=as76cb24eb
To: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.xxx.xxx.xxx:5060;transport=udp3>;tag=pttv1Xpyey0gj
Contact: <sip:3xxxxxxxxxx@188.xxx.xxx.xxx:5060>
Call-ID: 4351efb011df5b0e1db26b363e931d2c@188.xxx.xxx.xxx:5060
CSeq: 102 ACK
User-Agent: MOR Softswitch
Content-Length: 0

------------------------------------------------------------------------
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:174 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard REPORTING, cause: NORMAL_CLEARING
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State REPORTING going to sleep
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State Change CS_REPORTING -> CS_DESTROY
2018-02-13 15:56:21.368334 [DEBUG] switch_core_session.c:1665 Session 133 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Locked, Waiting on external entities
2018-02-13 15:56:21.368334 [NOTICE] switch_core_session.c:1683 Session 133 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Ended
2018-02-13 15:56:21.368334 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx [CS_DESTROY]
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) Running State Change CS_DESTROY (Cur 0 Tot 134)
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY
2018-02-13 15:56:21.368334 [DEBUG] mod_sofia.c:343 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx SOFIA DESTROY
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:181 sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx Standard DESTROY
2018-02-13 15:56:21.368334 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3xxxxxxxxxx@188.xxx.xxx.xxx) State DESTROY going to sleep
freeswitch@vpsXXXXXX.ovh.net> sofia global siptrace off
+OK Global siptrace off
freeswitch@vpsXXXXXX.ovh.net> /bye
root@vpsXXXXXX:~#

DigitalDaz · Feb 13, 2018

You must have an outbound route that is catching your extensions:

INVITE sip:100@voip.connecting-peoples.com SIP/2.0
Via: SIP/2.0/UDP 149.202.48.43;rport;branch=z9hG4bK3gg89p5ZZHjDa
Max-Forwards: 68
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930826 INVITE
Contact: <sip:gw+1d9c1c6c-14d9-45b5-a020-512905541a56@149.202.48.43:5060;transport=udp;gw=1d9c1c6c-14d9-45b5-a020-512905541a56>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 317
X-FS-Support: update_display,send_info
Remote-Party-ID: "3xxxxxxxxxx" <sip:3xxxxxxxxxx@voip.connecting-peoples.com>;party=calling;screen=no;privacy=off

v=0
o=FreeSWITCH 1518516963 1518516964 IN IP4 149.202.48.43
s=FreeSWITCH
c=IN IP4 149.202.48.43
t=0 0
m=audio 16816 RTP/AVP 8 9 0 3 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
recv 567 bytes from udp/[188.xxx.xxx.xxx]:5060 at 15:56:20.687480:
------------------------------------------------------------------------
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 149.202.48.43;branch=z9hG4bK3gg89p5ZZHjDa;received=149.202.48.43;rport=5060
From: "3xxxxxxxxxx" <sip:1619@voip.connecting-peoples.com>;tag=NH13Z25tHNayp
To: <sip:100@voip.connecting-peoples.com>;tag=as455f4232
Call-ID: e4a2639a-8b70-1236-0e87-fa163e15bfd5
CSeq: 118930826 INVITE
Server: MOR Softswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6191915c"

The call to extension 100 is going back out to the softswitch!

Massimiliano Iavazzo · Feb 13, 2018

Great!

I have removed a rule in outbound route with 3 digits that wrong matching 100 extension !

Thank you very much.

Massimiliano Iavazzo · Feb 13, 2018

A simple question: how can I specify into the Time Condition during a matching rule, to call an external number ?

Search

Search

Step by step inbound multi-tenant

Massimiliano Iavazzo

Member

DigitalDaz

Administrator

Massimiliano Iavazzo

Member

Massimiliano Iavazzo

Member

DigitalDaz

Administrator

Massimiliano Iavazzo

Member

DigitalDaz

Administrator

Massimiliano Iavazzo

Member

Massimiliano Iavazzo

Member

Massimiliano Iavazzo

Member

DigitalDaz

Administrator

Massimiliano Iavazzo

Member

DigitalDaz

Administrator

Massimiliano Iavazzo

Member

DigitalDaz

Administrator

Massimiliano Iavazzo

Member

Massimiliano Iavazzo

Member