Environment:
Debian 10 minimal install followed by FusionPBX magical script install, version 4.5.12
PBX is on a VPS which uses 1:1 NAT between private and public IP
One DID from Flowroute via SIP registration port 5080
Several IP phones at home which are also behind NAT as you would expect
Situation:
I'm migrating from a Debian 8 set up, with older FusionPBX, which was working fine at the same VPS provider.
I installed fresh and manually re-created my set up (could have missed some buried settings though)
Throughout the system the 'Context' is set to my FQDN (it originally was the private IP of the server). Maybe I did a bad thing there?
Domain (for example in Dialplan > Destination) is set to my FQDN, not Global which is a menu option.
I have changed, in vars, $${local_ip_v4} to now autonat:myextIP
Advanced > Access Controls > lan ... exists, but no nodes are specified there.
Advanced > Access Controls > domains, default deny, SIP trunk provider added as CIDR allowed and my server's internal IP is allowed in domain by IP.
Incoming calls did not work until I added the IP range of the Flowroute POP in domains, now incoming works.
NOW I CAN call from one extension to another. Previously even that was not working, but I think I had changed some settings and neglected to restart the sofia profiles.
Problem:
Cannot call out via SIP trunk, gives 480 Temporarily Unavailable error
It feels like this (updated) problem is not NAT-related.
* Call log:
Thanks in advance for any pointers!
Debian 10 minimal install followed by FusionPBX magical script install, version 4.5.12
PBX is on a VPS which uses 1:1 NAT between private and public IP
One DID from Flowroute via SIP registration port 5080
Several IP phones at home which are also behind NAT as you would expect
Situation:
I'm migrating from a Debian 8 set up, with older FusionPBX, which was working fine at the same VPS provider.
I installed fresh and manually re-created my set up (could have missed some buried settings though)
Throughout the system the 'Context' is set to my FQDN (it originally was the private IP of the server). Maybe I did a bad thing there?
Domain (for example in Dialplan > Destination) is set to my FQDN, not Global which is a menu option.
I have changed, in vars, $${local_ip_v4} to now autonat:myextIP
Advanced > Access Controls > lan ... exists, but no nodes are specified there.
Advanced > Access Controls > domains, default deny, SIP trunk provider added as CIDR allowed and my server's internal IP is allowed in domain by IP.
Incoming calls did not work until I added the IP range of the Flowroute POP in domains, now incoming works.
NOW I CAN call from one extension to another. Previously even that was not working, but I think I had changed some settings and neglected to restart the sofia profiles.
Problem:
Cannot call out via SIP trunk, gives 480 Temporarily Unavailable error
It feels like this (updated) problem is not NAT-related.
* Call log:
Code:
2020-03-27 20:11:28.434609 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/001@mypbx.example.net [dc93de9c-0f93-4a43-b24c-1c9f813cf150]
2020-03-27 20:11:28.434609 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/001@mypbx.example.net) Running State Change CS_NEW (Cur 1 Tot 11)
2020-03-27 20:11:28.434609 [DEBUG] sofia.c:10255 sofia/internal/001@mypbx.example.net receiving invite from callee.ext.ip.addr:11910 version: 1.10.2 -release-14-f7bdd3845a 64bit
2020-03-27 20:11:28.434609 [DEBUG] sofia.c:10349 verifying acl "domains" for ip/port callee.ext.ip.addr:0.
2020-03-27 20:11:28.454552 [DEBUG] sofia.c:2434 detaching session dc93de9c-0f93-4a43-b24c-1c9f813cf150
2020-03-27 20:11:28.454552 [WARNING] sofia_reg.c:1793 SIP auth challenge (INVITE) on sofia profile 'internal' for [18005551212@mypbx.example.net] from ip callee.ext.ip.addr
2020-03-27 20:11:28.454552 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/001@mypbx.example.net) State NEW
2020-03-27 20:11:28.594599 [DEBUG] sofia.c:2544 Re-attaching to session dc93de9c-0f93-4a43-b24c-1c9f813cf150
2020-03-27 20:11:28.614593 [DEBUG] sofia.c:10255 sofia/internal/001@mypbx.example.net receiving invite from callee.ext.ip.addr:11910 version: 1.10.2 -release-14-f7bdd3845a 64bit
2020-03-27 20:11:28.614593 [DEBUG] sofia.c:10349 verifying acl "domains" for ip/port callee.ext.ip.addr:0.
2020-03-27 20:11:28.614593 [DEBUG] sofia.c:11452 Setting NAT mode based on via received
2020-03-27 20:11:28.614593 [DEBUG] sofia.c:7301 Channel sofia/internal/001@mypbx.example.net entering state [received][100]
2020-03-27 20:11:28.614593 [DEBUG] sofia.c:7311 Remote SDP:
v=0
o=001 5020 45 IN IP4 192.168.1.111
s=Mapping
c=IN IP4 192.168.1.111
t=0 0
m=audio 5020 RTP/AVP 18 0 101
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
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 101@8000
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:3837 Set Codec sofia/internal/001@mypbx.example.net G729/8000 20 ms 160 samples 8000 bits 1 channels
2020-03-27 20:11:28.614593 [DEBUG] switch_core_codec.c:111 sofia/internal/001@mypbx.example.net Original read codec set to G729:18
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5851 Set telephone-event payload to 101@8000
2020-03-27 20:11:28.614593 [DEBUG] switch_core_media.c:5909 sofia/internal/001@mypbx.example.net Set 2833 dtmf send payload to 101 recv payload to 101
2020-03-27 20:11:28.614593 [DEBUG] sofia.c:7735 (sofia/internal/001@mypbx.example.net) State Change CS_NEW -> CS_INIT
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/001@mypbx.example.net) Running State Change CS_INIT (Cur 1 Tot 11)
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/001@mypbx.example.net) State INIT
2020-03-27 20:11:28.614593 [DEBUG] mod_sofia.c:93 sofia/internal/001@mypbx.example.net SOFIA INIT
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:40 sofia/internal/001@mypbx.example.net Standard INIT
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/001@mypbx.example.net) State Change CS_INIT -> CS_ROUTING
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/001@mypbx.example.net) State INIT going to sleep
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/001@mypbx.example.net) Running State Change CS_ROUTING (Cur 1 Tot 11)
2020-03-27 20:11:28.614593 [DEBUG] switch_channel.c:2332 (sofia/internal/001@mypbx.example.net) Callstate Change DOWN -> RINGING
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/001@mypbx.example.net) State ROUTING
2020-03-27 20:11:28.614593 [DEBUG] mod_sofia.c:154 sofia/internal/001@mypbx.example.net SOFIA ROUTING
2020-03-27 20:11:28.614593 [DEBUG] switch_core_state_machine.c:236 sofia/internal/001@mypbx.example.net Standard ROUTING
2020-03-27 20:11:28.614593 [INFO] mod_dialplan_xml.c:637 Processing home <001>->18005551212 in context mypbx.example.net
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->user_exists] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/001@mypbx.example.net Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(user_exists=false)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [user_exists]=[false]
Dialplan: sofia/internal/001@mypbx.example.net Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(from_user_exists=true)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [from_user_exists]=[true]
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call-direction] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net export(call_direction=local)
2020-03-27 20:11:28.634560 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->caller-details] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(caller_destination=18005551212)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [caller_destination]=[18005551212]
Dialplan: sofia/internal/001@mypbx.example.net Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(caller_id_name=001)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [caller_id_name]=[001]
Dialplan: sofia/internal/001@mypbx.example.net Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->global-variables] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/001@mypbx.example.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/001@mypbx.example.net Action set(timezone=Europe/London) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(timezone=Europe/London)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [timezone]=[Europe/London]
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->domain-variables] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/001@mypbx.example.net Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->is_loopback] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->user_record] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(from_user_record=)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [from_user_record]=[UNDEF]
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->redial] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [redial] destination_number(18005551212) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/001@mypbx.example.net Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->speed_dial] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [speed_dial] destination_number(18005551212) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->default_caller_id] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(emergency_caller_id_name=)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/001@mypbx.example.net Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(emergency_caller_id_number=)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(13102618661) =~ /^$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->us-east-nj.sip.flowroute.com.11d] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (PASS) [us-east-nj.sip.flowroute.com.11d] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [us-east-nj.sip.flowroute.com.11d] ${toll_allow}(international) =~ /true/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->home+mobile] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [home+mobile] destination_number(18005551212) =~ /^7779$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->casey mobiles] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [casey mobiles] destination_number(18005551212) =~ /^7778$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->agent_status] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [agent_status] destination_number(18005551212) =~ /^\*22$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [agent_status] destination_number(18005551212) =~ /^(agent\+)(.*)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->agent_status_id] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [agent_status_id] destination_number(18005551212) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->group-intercept] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [group-intercept] destination_number(18005551212) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->page-extension] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [page-extension] destination_number(18005551212) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->eavesdrop] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [eavesdrop] destination_number(18005551212) =~ /^\*33(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call_privacy] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call_privacy] destination_number(18005551212) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call_return] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call_return] destination_number(18005551212) =~ /^\*69$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [intercept-ext-polycom] destination_number(18005551212) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->intercept-ext] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [intercept-ext] destination_number(18005551212) =~ /^\*\*(\d+)$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [intercept-ext] destination_number(18005551212) =~ /^\*\*$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->extension_queue] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [extension_queue] destination_number(18005551212) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->dx] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [dx] destination_number(18005551212) =~ /^dx$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->Daytime to Hm+Mob] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [Daytime to Hm+Mob] destination_number(18005551212) =~ /^8000$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->send_to_voicemail] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [send_to_voicemail] destination_number(18005551212) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->extension-to-voicemail] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [extension-to-voicemail] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->att_xfer] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [att_xfer] destination_number(18005551212) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->vmain] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [vmain] destination_number(18005551212) =~ /^vmain$|^\*4000$|^\*98$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [vmain] destination_number(18005551212) =~ /^(vmain$|^\*4000$|^\*98)(\d{2,12})$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->xfer_vm] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [xfer_vm] destination_number(18005551212) =~ /^xfer_vm$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->vmain_user] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [vmain_user] destination_number(18005551212) =~ /^\*97$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->is_transfer] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [is_transfer] destination_number(18005551212) =~ /^is_transfer$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->cf] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [cf] destination_number(18005551212) =~ /^cf$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->delay_echo] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [delay_echo] destination_number(18005551212) =~ /^\*9195$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->echo] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [echo] destination_number(18005551212) =~ /^\*9196$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->is_zrtp_secure] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net ANTI-Action eval(not_secure)
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->milliwatt] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [milliwatt] destination_number(18005551212) =~ /^\*9197$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->is_secure] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->tone_stream] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [tone_stream] destination_number(18005551212) =~ /^\*9198$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->hold_music] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [hold_music] destination_number(18005551212) =~ /^\*9664$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->recordings] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [recordings] destination_number(18005551212) =~ /^\*(732)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->directory] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [directory] destination_number(18005551212) =~ /^\*411$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->wake-up] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [wake-up] destination_number(18005551212) =~ /^\*(925)$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->valet_park] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [valet_park] destination_number(18005551212) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [valet_park] destination_number(18005551212) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [valet_park] destination_number(18005551212) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->operator] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [operator] destination_number(18005551212) =~ /^0$|^operator$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->operator-forward] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [operator-forward] destination_number(18005551212) =~ /^\*000$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->do-not-disturb] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [do-not-disturb] destination_number(18005551212) =~ /^\*77$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [do-not-disturb] destination_number(18005551212) =~ /^\*78$|\*363$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [do-not-disturb] destination_number(18005551212) =~ /^\*79$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [do-not-disturb] destination_number(18005551212) =~ /^dnd\+001$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call_screen] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->follow-me-destinations] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [follow-me-destinations] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call-forward] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-forward] destination_number(18005551212) =~ /^\*72(\d*)$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-forward] destination_number(18005551212) =~ /^\*73$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-forward] destination_number(18005551212) =~ /^\*74$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-forward] destination_number(18005551212) =~ /^forward\+(\Q001\E)(?:\/(\d+))?$/ break=on-true
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call-forward-all] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-forward-all] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->call-forward-not-registered] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [call-forward-not-registered] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->follow-me] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [follow-me] destination_number(18005551212) =~ /^\*21$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->talking clock date and time] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [talking clock date and time] destination_number(18005551212) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->talking clock time] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [talking clock time] destination_number(18005551212) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->talking clock date] continue=
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [talking clock date] destination_number(18005551212) =~ /^\*9171$/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->local_extension] continue=true
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [local_extension] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/001@mypbx.example.net parsing [mypbx.example.net->voicemail] continue=false
Dialplan: sofia/internal/001@mypbx.example.net Regex (FAIL) [voicemail] ${user_exists}(false) =~ /true/ break=on-false
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/001@mypbx.example.net) State Change CS_ROUTING -> CS_EXECUTE
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/001@mypbx.example.net) State ROUTING going to sleep
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/001@mypbx.example.net) Running State Change CS_EXECUTE (Cur 1 Tot 11)
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/001@mypbx.example.net) State EXECUTE
2020-03-27 20:11:28.634560 [DEBUG] mod_sofia.c:209 sofia/internal/001@mypbx.example.net SOFIA EXECUTE
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:329 sofia/internal/001@mypbx.example.net Standard EXECUTE
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(caller_id_number=001)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [caller_id_number]=[001]
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net set(RFC2822_DATE=Fri, 27 Mar 2020 20:11:28 +0000)
2020-03-27 20:11:28.634560 [DEBUG] mod_dptools.c:1672 SET sofia/internal/001@mypbx.example.net [RFC2822_DATE]=[Fri, 27 Mar 2020 20:11:28 +0000]
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net export(origination_callee_id_name=18005551212)
2020-03-27 20:11:28.634560 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[18005551212]
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net hash(insert/mypbx.example.net-last_dial/001/18005551212)
EXECUTE [depth=0] sofia/internal/001@mypbx.example.net eval(not_secure)
2020-03-27 20:11:28.634560 [NOTICE] switch_core_state_machine.c:386 sofia/internal/001@mypbx.example.net has executed the last dialplan instruction, hanging up.
2020-03-27 20:11:28.634560 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/internal/001@mypbx.example.net [CS_EXECUTE] [NORMAL_CLEARING]
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/001@mypbx.example.net) State EXECUTE going to sleep
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/001@mypbx.example.net) Running State Change CS_HANGUP (Cur 1 Tot 11)
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/001@mypbx.example.net) Callstate Change RINGING -> HANGUP
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/001@mypbx.example.net) State HANGUP
2020-03-27 20:11:28.634560 [DEBUG] mod_sofia.c:453 Channel sofia/internal/001@mypbx.example.net hanging up, cause: NORMAL_CLEARING
2020-03-27 20:11:28.634560 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 480
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:60 sofia/internal/001@mypbx.example.net Standard HANGUP, cause: NORMAL_CLEARING
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/001@mypbx.example.net) State HANGUP going to sleep
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/001@mypbx.example.net) State Change CS_HANGUP -> CS_REPORTING
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/001@mypbx.example.net) Running State Change CS_REPORTING (Cur 1 Tot 11)
2020-03-27 20:11:28.634560 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/001@mypbx.example.net) State REPORTING
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:174 sofia/internal/001@mypbx.example.net Standard REPORTING, cause: NORMAL_CLEARING
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/001@mypbx.example.net) State REPORTING going to sleep
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/001@mypbx.example.net) State Change CS_REPORTING -> CS_DESTROY
2020-03-27 20:11:28.734551 [DEBUG] switch_core_session.c:1726 Session 11 (sofia/internal/001@mypbx.example.net) Locked, Waiting on external entities
2020-03-27 20:11:28.734551 [NOTICE] switch_core_session.c:1744 Session 11 (sofia/internal/001@mypbx.example.net) Ended
2020-03-27 20:11:28.734551 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/001@mypbx.example.net [CS_DESTROY]
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/001@mypbx.example.net) Running State Change CS_DESTROY (Cur 0 Tot 11)
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/001@mypbx.example.net) State DESTROY
2020-03-27 20:11:28.734551 [DEBUG] mod_sofia.c:364 sofia/internal/001@mypbx.example.net SOFIA DESTROY
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:181 sofia/internal/001@mypbx.example.net Standard DESTROY
2020-03-27 20:11:28.734551 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/001@mypbx.example.net) State DESTROY going to sleep
Thanks in advance for any pointers!
Last edited: