SOLVED Outbound Calls Suddenly Failing With Cause 41 Normal Temporary Failure Error

Msquared · Oct 5, 2020

I've banged my head against the wall all weekend reading various forums about this error, any help is much appreciated!

Background:
I've had FusionPBX up and running on an AWS instance for almost a year now without issue. I have a static IP assigned to my instance and I'm using a domain pointed to that IP/Instance. I'm currently on version 4.5.18 of FusionPBX. I use FlowRoute as my SIP provider.

Middle of last week I suddenly could not make outbound calls (inbound calling works fine). Looking at SNGREP, outbound calls make the invite, ACK, 100 Trying and then fail with "503 Service Unavailable".

The FlowRoute Gateway shows it's registered, inbound calling works, nothing has been changed in the ACL's .. I'm lost.

For ACL's
In the Domains I have defaulted to Deny and only had FlowRoute IP's listed in the CIDR.
The LAN section is empty.

As a temporary solution I created an account on Twilio, added Twilio to the Gateway and Outbound Route and all outbound calling started working again normally. Now inbound is coming from FlowRoute and all outbound calls are going to Twilio.

Again, any suggestions are much appreciated!!

Code:

82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.236373 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/201@4151234567.mydomain.com [82a3121e-91cd-4571-8548-72615fd05a28]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.236373 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_NEW (Cur 1 Tot 34)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.236373 [DEBUG] sofia.c:10243 sofia/internal/201@4151234567.mydomain.com receiving invite from 123.123.123.12:9636 version: 1.10.1 -release-12-f9990221e6 64bit
2020-09-30 18:02:55.236373 [DEBUG] sofia.c:10337 verifying acl "domains" for ip/port 123.123.123.12:0.
2020-09-30 18:02:55.236373 [WARNING] sofia_reg.c:1793 SIP auth challenge (INVITE) on sofia profile 'internal' for [14158675309@4151234567.mydomain.com] from ip 123.123.123.12
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.236373 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/201@4151234567.mydomain.com) State NEW
2020-09-30 18:02:55.236373 [DEBUG] sofia.c:2426 detaching session 82a3121e-91cd-4571-8548-72615fd05a28
2020-09-30 18:02:55.276368 [DEBUG] sofia.c:2535 Re-attaching to session 82a3121e-91cd-4571-8548-72615fd05a28
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.296361 [DEBUG] sofia.c:10243 sofia/internal/201@4151234567.mydomain.com receiving invite from 123.123.123.12:9636 version: 1.10.1 -release-12-f9990221e6 64bit
2020-09-30 18:02:55.296361 [DEBUG] sofia.c:10337 verifying acl "domains" for ip/port 123.123.123.12:0.
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] sofia.c:11433 Setting NAT mode based on via received
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] sofia.c:7290 Channel sofia/internal/201@4151234567.mydomain.com entering state [received][100]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] sofia.c:7300 ReABCe SDP:
82a3121e-91cd-4571-8548-72615fd05a28 v=0
82a3121e-91cd-4571-8548-72615fd05a28 o=- 3810477811 3810477811 IN IP4 10.10.10.20
82a3121e-91cd-4571-8548-72615fd05a28 s=pjmedia
82a3121e-91cd-4571-8548-72615fd05a28 b=AS:84
82a3121e-91cd-4571-8548-72615fd05a28 t=0 0
82a3121e-91cd-4571-8548-72615fd05a28 a=X-nat:0
82a3121e-91cd-4571-8548-72615fd05a28 m=audio 4044 RTP/AVP 9 96 97 98 99 100 3 0 8 101 102 103
82a3121e-91cd-4571-8548-72615fd05a28 c=IN IP4 10.10.10.20
82a3121e-91cd-4571-8548-72615fd05a28 b=TIAS:64000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:9 G722/8000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:96 G7221/16000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:96 bitrate=24000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:97 G7221/16000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:97 bitrate=32000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:98 G7221/32000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:98 bitrate=24000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:99 G7221/32000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:99 bitrate=32000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:100 G7221/32000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:100 bitrate=48000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:3 GSM/8000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:0 PCMU/8000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:8 PCMA/8000
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:101 telephone-event/8000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:101 0-16
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:102 telephone-event/16000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:102 0-16
82a3121e-91cd-4571-8548-72615fd05a28 a=rtpmap:103 telephone-event/32000
82a3121e-91cd-4571-8548-72615fd05a28 a=fmtp:103 0-16
82a3121e-91cd-4571-8548-72615fd05a28 a=rtcp:4045 IN IP4 10.10.10.20
82a3121e-91cd-4571-8548-72615fd05a28 a=ssrc:1640628740 cname:359c55d7472c708c
82a3121e-91cd-4571-8548-72615fd05a28
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:96:16000:20:0:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:96:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:96:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:97:16000:20:0:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:97:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:97:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:98:32000:20:0:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:98:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:98:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:99:32000:20:0:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:99:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:99:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:100:32000:20:0:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:100:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:100:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:3834 Set Codec sofia/internal/201@4151234567.mydomain.com G722/8000 20 ms 160 samples 64000 bits 1 channels
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_codec.c:111 sofia/internal/201@4151234567.mydomain.com Original read codec set to G722:9
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_media.c:5907 sofia/internal/201@4151234567.mydomain.com Set 2833 dtmf send payload to 101 recv payload to 101
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] sofia.c:7724 (sofia/internal/201@4151234567.mydomain.com) State Change CS_NEW -> CS_INIT
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_INIT (Cur 1 Tot 34)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/201@4151234567.mydomain.com) State INIT
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] mod_sofia.c:93 sofia/internal/201@4151234567.mydomain.com SOFIA INIT
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:40 sofia/internal/201@4151234567.mydomain.com Standard INIT
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/201@4151234567.mydomain.com) State Change CS_INIT -> CS_ROUTING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/201@4151234567.mydomain.com) State INIT going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_ROUTING (Cur 1 Tot 34)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_channel.c:2332 (sofia/internal/201@4151234567.mydomain.com) Callstate Change DOWN -> RINGING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/201@4151234567.mydomain.com) State ROUTING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] mod_sofia.c:154 sofia/internal/201@4151234567.mydomain.com SOFIA ROUTING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [DEBUG] switch_core_state_machine.c:236 sofia/internal/201@4151234567.mydomain.com Standard ROUTING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.316367 [INFO] mod_dialplan_xml.c:637 Processing Ext 201 <201>->14158675309 in context 4151234567.mydomain.com
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->user_exists] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_exists] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(user_exists=false)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [user_exists]=[false]
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(from_user_exists=true)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [from_user_exists]=[true]
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->caller-details] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(caller_destination=${destination_number}) INLINE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(caller_destination=14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [caller_destination]=[14158675309]
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(caller_id_name=${caller_id_name}) INLINE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(caller_id_name=201)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [caller_id_name]=[201]
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(caller_id_number=${caller_id_number})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->call-direction] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com ANTI-Action export(call_direction=local) INLINE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com export(call_direction=local)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->global-variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->variables] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [variables] () =~ // break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action export(origination_callee_id_name=${destination_number})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->is_loopback] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->call_block] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [call_block] ${call_direction}(local) =~ /^inbound$/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->user_record] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(from_user_record=)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [from_user_record]=[UNDEF]
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->redial] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [redial] destination_number(14158675309) =~ /^(redial|\*870)$/ break=on-true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [redial] () =~ // break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->speed_dial] continue=false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [speed_dial] destination_number(14158675309) =~ /^\*0(.*)$/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->user_hold_music] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->default_caller_id] continue=true
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [default_caller_id] ${emergency_caller_id_number}(14151234567) =~ /^$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(14151234567) =~ /^$/ break=never
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->Flowroute.911] continue=false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [Flowroute.911] ${user_exists}(false) =~ /false/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (FAIL) [Flowroute.911] destination_number(14158675309) =~ /(^911$|^933$)/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com parsing [4151234567.mydomain.com->ABC Flowroute.11d] continue=false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [ABC Flowroute.11d] ${user_exists}(false) =~ /false/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Regex (PASS) [ABC Flowroute.11d] destination_number(14158675309) =~ /^\+?(\d{11})$/ break=on-false
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(sip_h_X-accountcode=${accountcode})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action export(call_direction=outbound)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action unset(call_timeout)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(hangup_after_bridge=true)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(effective_caller_id_name=${outbound_caller_id_name})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(effective_caller_id_number=${outbound_caller_id_number})
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(inherit_codec=true)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(ignore_display_updates=true)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(callee_id_number=14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(continue_on_fail=true)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action set(provider_prefix=99999999*)
82a3121e-91cd-4571-8548-72615fd05a28 Dialplan: sofia/internal/201@4151234567.mydomain.com Action bridge(sofia/gateway/c78af767-7d65-4f79-a197-71600567fa8f/99999999*14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/201@4151234567.mydomain.com) State Change CS_ROUTING -> CS_EXECUTE
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/201@4151234567.mydomain.com) State ROUTING going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_EXECUTE (Cur 1 Tot 34)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/201@4151234567.mydomain.com) State EXECUTE
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_sofia.c:209 sofia/internal/201@4151234567.mydomain.com SOFIA EXECUTE
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_core_state_machine.c:329 sofia/internal/201@4151234567.mydomain.com Standard EXECUTE
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(caller_id_number=201)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [caller_id_number]=[201]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com export(origination_callee_id_name=14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[14158675309]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(RFC2822_DATE=Wed, 30 Sep 2020 18:02:55 -0700)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [RFC2822_DATE]=[Wed, 30 Sep 2020 18:02:55 -0700]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com hash(insert/4151234567.mydomain.com-last_dial/201/14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(sip_h_X-accountcode=)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [sip_h_X-accountcode]=[UNDEF]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com export(call_direction=outbound)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[outbound]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com unset(call_timeout)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1817 UNSET [call_timeout]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(hangup_after_bridge=true)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [hangup_after_bridge]=[true]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(effective_caller_id_name=ABC CORP)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [effective_caller_id_name]=[ABC CORP]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(effective_caller_id_number=14151234567)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [effective_caller_id_number]=[14151234567]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(inherit_codec=true)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [inherit_codec]=[true]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(ignore_display_updates=true)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [ignore_display_updates]=[true]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(callee_id_number=14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [callee_id_number]=[14158675309]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(continue_on_fail=true)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [continue_on_fail]=[true]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com set(provider_prefix=99999999*)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] mod_dptools.c:1672 SET sofia/internal/201@4151234567.mydomain.com [provider_prefix]=[99999999*]
82a3121e-91cd-4571-8548-72615fd05a28 EXECUTE [depth=0] sofia/internal/201@4151234567.mydomain.com bridge(sofia/gateway/c78af767-7d65-4f79-a197-71600567fa8f/99999999*14158675309)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1264 sofia/internal/201@4151234567.mydomain.com EXPORTING[export_vars] [domain_name]=[4151234567.mydomain.com] to event
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1264 sofia/internal/201@4151234567.mydomain.com EXPORTING[export_vars] [call_direction]=[outbound] to event
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1264 sofia/internal/201@4151234567.mydomain.com EXPORTING[export_vars] [origination_callee_id_name]=[14158675309] to event
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_channel.c:1264 sofia/internal/201@4151234567.mydomain.com EXPORTING[export_vars] [call_direction]=[outbound] to event
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.336362 [DEBUG] switch_ivr_originate.c:2212 Parsing global variables
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.336362 [NOTICE] switch_channel.c:1118 New Channel sofia/external/99999999*14158675309 [2d76b83d-5a0f-42d1-b039-b46d684cbd37]
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.336362 [DEBUG] mod_sofia.c:5096 (sofia/external/99999999*14158675309) State Change CS_NEW -> CS_INIT
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:585 (sofia/external/99999999*14158675309) Running State Change CS_INIT (Cur 2 Tot 35)
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:628 (sofia/external/99999999*14158675309) State INIT
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:93 sofia/external/99999999*14158675309 SOFIA INIT
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] sofia_glue.c:1618 sofia/external/99999999*14158675309 sending invite version: 1.10.1 -release-12-f9990221e6 64bit
2d76b83d-5a0f-42d1-b039-b46d684cbd37 Local SDP:
2d76b83d-5a0f-42d1-b039-b46d684cbd37 v=0
2d76b83d-5a0f-42d1-b039-b46d684cbd37 o=FreeSWITCH 1601486153 1601486154 IN IP4 123.123.123.13
2d76b83d-5a0f-42d1-b039-b46d684cbd37 s=FreeSWITCH
2d76b83d-5a0f-42d1-b039-b46d684cbd37 c=IN IP4 123.123.123.13
2d76b83d-5a0f-42d1-b039-b46d684cbd37 t=0 0
2d76b83d-5a0f-42d1-b039-b46d684cbd37 m=audio 28022 RTP/AVP 9 0 8 101 13
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=rtpmap:9 G722/8000
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=rtpmap:0 PCMU/8000
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=rtpmap:8 PCMA/8000
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=rtpmap:101 telephone-event/8000
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=fmtp:101 0-16
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=rtpmap:13 CN/8000
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=ptime:20
2d76b83d-5a0f-42d1-b039-b46d684cbd37 a=sendrecv
2d76b83d-5a0f-42d1-b039-b46d684cbd37
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:40 sofia/external/99999999*14158675309 Standard INIT
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:48 (sofia/external/99999999*14158675309) State Change CS_INIT -> CS_ROUTING
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:628 (sofia/external/99999999*14158675309) State INIT going to sleep
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:585 (sofia/external/99999999*14158675309) Running State Change CS_ROUTING (Cur 2 Tot 35)
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] sofia.c:7290 Channel sofia/external/99999999*14158675309 entering state [calling][0]
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] sofia.c:7290 Channel sofia/external/99999999*14158675309 entering state [terminated][503]
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [NOTICE] sofia.c:8523 Hangup sofia/external/99999999*14158675309 [CS_ROUTING] [NORMAL_TEMPORARY_FAILURE]
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:644 (sofia/external/99999999*14158675309) State ROUTING
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:154 sofia/external/99999999*14158675309 SOFIA ROUTING
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:644 (sofia/external/99999999*14158675309) State ROUTING going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_ivr_originate.c:3949 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:585 (sofia/external/99999999*14158675309) Running State Change CS_HANGUP (Cur 2 Tot 35)
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:848 (sofia/external/99999999*14158675309) Callstate Change DOWN -> HANGUP
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:850 (sofia/external/99999999*14158675309) State HANGUP
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:460 Channel sofia/external/99999999*14158675309 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:60 sofia/external/99999999*14158675309 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:850 (sofia/external/99999999*14158675309) State HANGUP going to sleep
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:620 (sofia/external/99999999*14158675309) State Change CS_HANGUP -> CS_REPORTING
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:585 (sofia/external/99999999*14158675309) Running State Change CS_REPORTING (Cur 2 Tot 35)
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:936 (sofia/external/99999999*14158675309) State REPORTING
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:174 sofia/external/99999999*14158675309 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:936 (sofia/external/99999999*14158675309) State REPORTING going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [INFO] mod_dptools.c:3631 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:611 (sofia/external/99999999*14158675309) State Change CS_REPORTING -> CS_DESTROY
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_session.c:1726 Session 35 (sofia/external/99999999*14158675309) Locked, Waiting on external entities
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [NOTICE] switch_core_session.c:1744 Session 35 (sofia/external/99999999*14158675309) Ended
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/99999999*14158675309 [CS_DESTROY]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [NOTICE] switch_core_state_machine.c:386 sofia/internal/201@4151234567.mydomain.com has executed the last dialplan instruction, hanging up.
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/internal/201@4151234567.mydomain.com [CS_EXECUTE] [NORMAL_CLEARING]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/201@4151234567.mydomain.com) State EXECUTE going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_HANGUP (Cur 1 Tot 35)
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:739 (sofia/external/99999999*14158675309) Running State Change CS_DESTROY (Cur 1 Tot 35)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/201@4151234567.mydomain.com) Callstate Change RINGING -> HANGUP
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:749 (sofia/external/99999999*14158675309) State DESTROY
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:365 sofia/external/99999999*14158675309 SOFIA DESTROY
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:181 sofia/external/99999999*14158675309 Standard DESTROY
2d76b83d-5a0f-42d1-b039-b46d684cbd37 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:749 (sofia/external/99999999*14158675309) State DESTROY going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/201@4151234567.mydomain.com) State HANGUP
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:454 sofia/internal/201@4151234567.mydomain.com Overriding SIP cause 480 with 503 from the other leg
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:460 Channel sofia/internal/201@4151234567.mydomain.com hanging up, cause: NORMAL_CLEARING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] mod_sofia.c:605 Responding to INVITE with: 503
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:60 sofia/internal/201@4151234567.mydomain.com Standard HANGUP, cause: NORMAL_CLEARING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/201@4151234567.mydomain.com) State HANGUP going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/201@4151234567.mydomain.com) State Change CS_HANGUP -> CS_REPORTING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_REPORTING (Cur 1 Tot 35)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.356362 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/201@4151234567.mydomain.com) State REPORTING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:174 sofia/internal/201@4151234567.mydomain.com Standard REPORTING, cause: NORMAL_CLEARING
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/201@4151234567.mydomain.com) State REPORTING going to sleep
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/201@4151234567.mydomain.com) State Change CS_REPORTING -> CS_DESTROY
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_session.c:1726 Session 34 (sofia/internal/201@4151234567.mydomain.com) Locked, Waiting on external entities
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [NOTICE] switch_core_session.c:1744 Session 34 (sofia/internal/201@4151234567.mydomain.com) Ended
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/201@4151234567.mydomain.com [CS_DESTROY]
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/201@4151234567.mydomain.com) Running State Change CS_DESTROY (Cur 0 Tot 35)
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/201@4151234567.mydomain.com) State DESTROY
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] mod_sofia.c:365 sofia/internal/201@4151234567.mydomain.com SOFIA DESTROY
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:181 sofia/internal/201@4151234567.mydomain.com Standard DESTROY
82a3121e-91cd-4571-8548-72615fd05a28 2020-09-30 18:02:55.416369 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/201@4151234567.mydomain.com) State DESTROY going to sleep

DigitalDaz · Oct 5, 2020

You either need to sngrep it or get sip tracing on with: sofia global siptrace on

Its possibly nothing to do with you and could be a carrier change. You need to see if the carrier is rejecting it.

Msquared · Oct 6, 2020

Thank you for the reply DigitalDaz.

The 503 is coming from FreeSwitch before it ever reaches out to the carrier. Any idea why?

I've tried deleting the FlowRoute Gateway & Outbound Route from Fusion and recreating it, but it did not help. I have a fairly default Dialplan, the only change I've made is add the FlowRoute required tech prefix e.g. sofia/gateway/flowroute/123456*1$1

Msquared · Oct 7, 2020

DigitalDaz said:
You either need to sngrep it or get sip tracing on with: sofia global siptrace on

Its possibly nothing to do with you and could be a carrier change. You need to see if the carrier is rejecting it.

I am not finding any issues with sofia/internal, I can see where it changes call_direction to an outbound call and opens a new channel on sofia/external and routing starts but immediately terminates with 503.

2020-10-07 00:36:29.682231 [DEBUG] sofia.c:7290 Channel sofia/external/135790*14152225555 entering state [calling][0]
2020-10-07 00:36:29.682231 [DEBUG] sofia.c:7290 Channel sofia/external/135790*14152225555 entering state [terminated][503]
2020-10-07 00:36:29.682231 [NOTICE] sofia.c:8523 Hangup sofia/external/135790*14152225555 [CS_ROUTING] [NORMAL_TEMPORARY_FAILURE]

2020-10-07 00:36:29.702224 [DEBUG] switch_ivr_originate.c:3949 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]

2020-10-07 00:36:29.702224 [DEBUG] mod_sofia.c:454 sofia/internal/8201@my.pbxdomain.net Overriding SIP cause 480 with 503 from the other leg

I've confirmed with FlowRoute (SIP Provider) they are not seeing an INVITE from this server for any outbound calls, but inbound calls using the same Flowroute Gateway are working.

I've also tried registering to a different FlowRoute datacenter, rebuilt the Gateway & Outbound Route.

This FusionPBX server is a multi-tenant cloud server, the same outbound calling issue is across all phones, multiple locations, each using their own account on Flowroute & Gateway/Outbound Route configuration on FusionPBX. I've also confirmed the security rules on AWS do not limit outbound traffic.

Do you have any ideas on what I could try next or any pointers on where to research? Thank you for your help!!

Code:

INVITE sip:14152225555@my.pbxdomain.net SIP/2.0
Via: SIP/2.0/TCP 10.10.10.20:29833;rport;branch=z9hG4bKPja561fd352d524bb09c66606a1e9bff55;alias
Max-Forwards: 70
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>
Contact: "Ext 8201" <sip:8201@10.10.10.20:54488;ob>
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24482 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: MicroSIP/3.20.1
Content-Type: application/sdp
Content-Length:   766

v=0
o=- 3811019827 3811019827 IN IP4 10.10.10.20
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4006 RTP/AVP 9 96 97 98 99 100 3 0 8 101 102 103
c=IN IP4 10.10.10.20
b=TIAS:64000
a=rtcp:4007 IN IP4 10.10.10.20
a=sendrecv
a=rtpmap:9 G722/8000
a=rtpmap:96 G7221/16000
a=fmtp:96 bitrate=24000
a=rtpmap:97 G7221/16000
a=fmtp:97 bitrate=32000
a=rtpmap:98 G7221/32000
a=fmtp:98 bitrate=24000
a=rtpmap:99 G7221/32000
a=fmtp:99 bitrate=32000
a=rtpmap:100 G7221/32000
a=fmtp:100 bitrate=48000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:102 telephone-event/16000
a=fmtp:102 0-16
a=rtpmap:103 telephone-event/32000
a=fmtp:103 0-16
a=ssrc:1607759856 cname:18a7288a4adc2467
2020-10-07 00:36:29.582232 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/8201@my.pbxdomain.net [351bee93-124d-4d27-bb92-8e59f47b5989]
2020-10-07 00:36:29.582232 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_NEW (Cur 1 Tot 32)
2020-10-07 00:36:29.582232 [DEBUG] sofia.c:10243 sofia/internal/8201@my.pbxdomain.net receiving invite from 111.22.33.4:29833 version: 1.10.1 -release-12-f9990221e6 64bit
2020-10-07 00:36:29.582232 [DEBUG] sofia.c:10337 verifying acl "domains" for ip/port 111.22.33.4:0.
2020-10-07 00:36:29.582232 [WARNING] sofia_reg.c:1793 SIP auth challenge (INVITE) on sofia profile 'internal' for [14152225555@my.pbxdomain.net] from ip 111.22.33.4
2020-10-07 00:36:29.582232 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/8201@my.pbxdomain.net) State NEW
send 897 bytes to tcp/[111.22.33.4]:29833 at 00:37:06.653259:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TCP 10.10.10.20:29833;rport=29833;branch=z9hG4bKPja561fd352d524bb09c66606a1e9bff55;alias;received=111.22.33.4
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>;tag=rH3Q0HH9pH3am
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24482 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
Proxy-Authenticate: Digest realm="my.pbxdomain.net", nonce="ba09c461-0542-493f-b90a-5af777e3c9a0", algorithm=MD5, qop="auth"
Content-Length: 0

2020-10-07 00:36:29.582232 [DEBUG] sofia.c:2426 detaching session 351bee93-124d-4d27-bb92-8e59f47b5989
recv 396 bytes from tcp/[111.22.33.4]:29833 at 00:37:06.689457:
------------------------------------------------------------------------
ACK sip:14152225555@my.pbxdomain.net SIP/2.0
Via: SIP/2.0/TCP 10.10.10.20:29833;rport;branch=z9hG4bKPja561fd352d524bb09c66606a1e9bff55;alias
Max-Forwards: 70
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>;tag=rH3Q0HH9pH3am
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24482 ACK
Content-Length:  0

recv 1738 bytes from tcp/[111.22.33.4]:29833 at 00:37:06.695216:
------------------------------------------------------------------------
INVITE sip:14152225555@my.pbxdomain.net SIP/2.0
Via: SIP/2.0/TCP 10.10.10.20:29833;rport;branch=z9hG4bKPjeebfcabb4e5b46cf943d2ff9b0f00ce5;alias
Max-Forwards: 70
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>
Contact: "Ext 8201" <sip:8201@10.10.10.20:54488;ob>
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24483 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: MicroSIP/3.20.1
Proxy-Authorization: Digest username="8201", realm="my.pbxdomain.net", nonce="ba09c461-0542-493f-b90a-5af777e3c9a0", uri="sip:14152225555@my.pbxdomain.net", response="9156fa3ec89c41c7f95ef79ba6365072", algorithm=MD5, cnonce="71de59642b1e48ffb667b40df3708911", qop=auth, nc=00000001
Content-Type: application/sdp
Content-Length:   766

v=0
o=- 3811019827 3811019827 IN IP4 10.10.10.20
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4006 RTP/AVP 9 96 97 98 99 100 3 0 8 101 102 103
c=IN IP4 10.10.10.20
b=TIAS:64000
a=rtcp:4007 IN IP4 10.10.10.20
a=sendrecv
a=rtpmap:9 G722/8000
a=rtpmap:96 G7221/16000
a=fmtp:96 bitrate=24000
a=rtpmap:97 G7221/16000
a=fmtp:97 bitrate=32000
a=rtpmap:98 G7221/32000
a=fmtp:98 bitrate=24000
a=rtpmap:99 G7221/32000
a=fmtp:99 bitrate=32000
a=rtpmap:100 G7221/32000
a=fmtp:100 bitrate=48000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:102 telephone-event/16000
a=fmtp:102 0-16
a=rtpmap:103 telephone-event/32000
a=fmtp:103 0-16
a=ssrc:1607759856 cname:18a7288a4adc2467
2020-10-07 00:36:29.622233 [DEBUG] sofia.c:2535 Re-attaching to session 351bee93-124d-4d27-bb92-8e59f47b5989
2020-10-07 00:36:29.642233 [DEBUG] sofia.c:10243 sofia/internal/8201@my.pbxdomain.net receiving invite from 111.22.33.4:29833 version: 1.10.1 -release-12-f9990221e6 64bit
2020-10-07 00:36:29.642233 [DEBUG] sofia.c:10337 verifying acl "domains" for ip/port 111.22.33.4:0.
2020-10-07 00:36:29.642233 [DEBUG] sofia.c:11433 Setting NAT mode based on via received
2020-10-07 00:36:29.642233 [DEBUG] sofia.c:7290 Channel sofia/internal/8201@my.pbxdomain.net entering state [received][100]
2020-10-07 00:36:29.642233 [DEBUG] sofia.c:7300 Remote SDP:
v=0
o=- 3811019827 3811019827 IN IP4 10.10.10.20
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4006 RTP/AVP 9 96 97 98 99 100 3 0 8 101 102 103
c=IN IP4 10.10.10.20
b=TIAS:64000
a=rtpmap:9 G722/8000
a=rtpmap:96 G7221/16000
a=fmtp:96 bitrate=24000
a=rtpmap:97 G7221/16000
a=fmtp:97 bitrate=32000
a=rtpmap:98 G7221/32000
a=fmtp:98 bitrate=24000
a=rtpmap:99 G7221/32000
a=fmtp:99 bitrate=32000
a=rtpmap:100 G7221/32000
a=fmtp:100 bitrate=48000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:102 telephone-event/16000
a=fmtp:102 0-16
a=rtpmap:103 telephone-event/32000
a=fmtp:103 0-16
a=rtcp:4007 IN IP4 10.10.10.20
a=ssrc:1607759856 cname:18a7288a4adc2467

2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:96:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:96:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:96:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:97:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:97:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:97:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:98:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:98:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:98:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:99:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:99:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:99:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:100:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:100:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G7221:100:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:3834 Set Codec sofia/internal/8201@my.pbxdomain.net G722/8000 20 ms 160 samples 64000 bits 1 channels
2020-10-07 00:36:29.642233 [DEBUG] switch_core_codec.c:111 sofia/internal/8201@my.pbxdomain.net Original read codec set to G722:9
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000
2020-10-07 00:36:29.642233 [DEBUG] switch_core_media.c:5907 sofia/internal/8201@my.pbxdomain.net Set 2833 dtmf send payload to 101 recv payload to 101
2020-10-07 00:36:29.642233 [DEBUG] sofia.c:7724 (sofia/internal/8201@my.pbxdomain.net) State Change CS_NEW -> CS_INIT
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_INIT (Cur 1 Tot 32)
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/8201@my.pbxdomain.net) State INIT
2020-10-07 00:36:29.642233 [DEBUG] mod_sofia.c:93 sofia/internal/8201@my.pbxdomain.net SOFIA INIT
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:40 sofia/internal/8201@my.pbxdomain.net Standard INIT
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/8201@my.pbxdomain.net) State Change CS_INIT -> CS_ROUTING
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/8201@my.pbxdomain.net) State INIT going to sleep
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_ROUTING (Cur 1 Tot 32)
2020-10-07 00:36:29.642233 [DEBUG] switch_channel.c:2332 (sofia/internal/8201@my.pbxdomain.net) Callstate Change DOWN -> RINGING
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/8201@my.pbxdomain.net) State ROUTING
send 386 bytes to tcp/[111.22.33.4]:29833 at 00:37:06.720485:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.10.10.20:29833;rport=29833;branch=z9hG4bKPjeebfcabb4e5b46cf943d2ff9b0f00ce5;alias;received=111.22.33.4
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24483 INVITE
User-Agent: FreeSWITCH
Content-Length: 0

2020-10-07 00:36:29.642233 [DEBUG] mod_sofia.c:154 sofia/internal/8201@my.pbxdomain.net SOFIA ROUTING
2020-10-07 00:36:29.642233 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8201@my.pbxdomain.net Standard ROUTING
2020-10-07 00:36:29.642233 [INFO] mod_dialplan_xml.c:637 Processing Ext 8201 <8201>->14152225555 in context my.pbxdomain.net
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->user_exists] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(user_exists=false)
2020-10-07 00:36:29.662225 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [user_exists]=[false]
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(from_user_exists=true)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [from_user_exists]=[true]
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->caller-details] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(caller_destination=14152225555)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [caller_destination]=[14152225555]
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(caller_id_name=8201)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [caller_id_name]=[8201]
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->call-direction] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net export(call_direction=local)
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->global-variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->variables] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->is_loopback] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->call_block] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [call_block] ${call_direction}(local) =~ /^inbound$/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->user_record] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(from_user_record=)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [from_user_record]=[UNDEF]
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->redial] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [redial] destination_number(14152225555) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->speed_dial] continue=false
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [speed_dial] destination_number(14152225555) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->user_hold_music] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->default_caller_id] continue=true
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [default_caller_id] ${emergency_caller_id_number}(18885551212) =~ /^$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(18885551212) =~ /^$/ break=never
Dialplan: sofia/internal/8201@my.pbxdomain.net parsing [my.pbxdomain.net->Flowroute.1d10] continue=false
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [Flowroute.1d10] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Regex (PASS) [Flowroute.1d10] destination_number(14152225555) =~ /^\+?1?(\d{10})$/ break=on-false
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/8201@my.pbxdomain.net Action export(call_direction=outbound)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action unset(call_timeout)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(inherit_codec=true)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(ignore_display_updates=true)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(callee_id_number=4152225555)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action set(continue_on_fail=true)
Dialplan: sofia/internal/8201@my.pbxdomain.net Action bridge(sofia/gateway/231483e3-a41c-4e9c-8c74-453cf35c63e5/135790*14152225555)
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/8201@my.pbxdomain.net) State Change CS_ROUTING -> CS_EXECUTE
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/8201@my.pbxdomain.net) State ROUTING going to sleep
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_EXECUTE (Cur 1 Tot 32)
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/8201@my.pbxdomain.net) State EXECUTE
2020-10-07 00:36:29.682231 [DEBUG] mod_sofia.c:209 sofia/internal/8201@my.pbxdomain.net SOFIA EXECUTE
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:329 sofia/internal/8201@my.pbxdomain.net Standard EXECUTE
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(caller_id_number=8201)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [caller_id_number]=[8201]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net export(origination_callee_id_name=14152225555)
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[14152225555]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(RFC2822_DATE=Wed, 07 Oct 2020 00:36:29 -0700)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [RFC2822_DATE]=[Wed, 07 Oct 2020 00:36:29 -0700]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net hash(insert/my.pbxdomain.net-last_dial/8201/14152225555)
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(sip_h_X-accountcode=)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [sip_h_X-accountcode]=[UNDEF]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net export(call_direction=outbound)
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[outbound]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net unset(call_timeout)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1817 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(hangup_after_bridge=true)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(effective_caller_id_name=ABC CORP)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [effective_caller_id_name]=[ABC CORP]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(effective_caller_id_number=18885551212)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [effective_caller_id_number]=[18885551212]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(inherit_codec=true)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(ignore_display_updates=true)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(callee_id_number=4152225555)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [callee_id_number]=[4152225555]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net set(continue_on_fail=true)
2020-10-07 00:36:29.682231 [DEBUG] mod_dptools.c:1672 SET sofia/internal/8201@my.pbxdomain.net [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/internal/8201@my.pbxdomain.net bridge(sofia/gateway/231483e3-a41c-4e9c-8c74-453cf35c63e5/135790*14152225555)
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1264 sofia/internal/8201@my.pbxdomain.net EXPORTING[export_vars] [domain_name]=[my.pbxdomain.net] to event
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1264 sofia/internal/8201@my.pbxdomain.net EXPORTING[export_vars] [call_direction]=[outbound] to event
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1264 sofia/internal/8201@my.pbxdomain.net EXPORTING[export_vars] [origination_callee_id_name]=[14152225555] to event
2020-10-07 00:36:29.682231 [DEBUG] switch_channel.c:1264 sofia/internal/8201@my.pbxdomain.net EXPORTING[export_vars] [call_direction]=[outbound] to event
2020-10-07 00:36:29.682231 [DEBUG] switch_ivr_originate.c:2212 Parsing global variables
2020-10-07 00:36:29.682231 [NOTICE] switch_channel.c:1118 New Channel sofia/external/135790*14152225555 [323889f2-fad3-455f-a755-4ac4478c5641]
2020-10-07 00:36:29.682231 [DEBUG] mod_sofia.c:5096 (sofia/external/135790*14152225555) State Change CS_NEW -> CS_INIT
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:585 (sofia/external/135790*14152225555) Running State Change CS_INIT (Cur 2 Tot 33)
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:628 (sofia/external/135790*14152225555) State INIT
2020-10-07 00:36:29.682231 [DEBUG] mod_sofia.c:93 sofia/external/135790*14152225555 SOFIA INIT
2020-10-07 00:36:29.682231 [DEBUG] sofia_glue.c:1618 sofia/external/135790*14152225555 sending invite version: 1.10.1 -release-12-f9990221e6 64bit
Local SDP:
v=0
o=FreeSWITCH 1602024111 1602024112 IN IP4 11.222.33.44
s=FreeSWITCH
c=IN IP4 11.222.33.44
t=0 0
m=audio 32078 RTP/AVP 9 0 8 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:40 sofia/external/135790*14152225555 Standard INIT
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:48 (sofia/external/135790*14152225555) State Change CS_INIT -> CS_ROUTING
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:628 (sofia/external/135790*14152225555) State INIT going to sleep
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:585 (sofia/external/135790*14152225555) Running State Change CS_ROUTING (Cur 2 Tot 33)
2020-10-07 00:36:29.682231 [DEBUG] sofia.c:7290 Channel sofia/external/135790*14152225555 entering state [calling][0]
2020-10-07 00:36:29.682231 [DEBUG] sofia.c:7290 Channel sofia/external/135790*14152225555 entering state [terminated][503]
2020-10-07 00:36:29.682231 [NOTICE] sofia.c:8523 Hangup sofia/external/135790*14152225555 [CS_ROUTING] [NORMAL_TEMPORARY_FAILURE]
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:644 (sofia/external/135790*14152225555) State ROUTING
2020-10-07 00:36:29.682231 [DEBUG] mod_sofia.c:154 sofia/external/135790*14152225555 SOFIA ROUTING
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:644 (sofia/external/135790*14152225555) State ROUTING going to sleep
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:585 (sofia/external/135790*14152225555) Running State Change CS_HANGUP (Cur 2 Tot 33)
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:848 (sofia/external/135790*14152225555) Callstate Change DOWN -> HANGUP
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:850 (sofia/external/135790*14152225555) State HANGUP
2020-10-07 00:36:29.682231 [DEBUG] mod_sofia.c:460 Channel sofia/external/135790*14152225555 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:60 sofia/external/135790*14152225555 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:850 (sofia/external/135790*14152225555) State HANGUP going to sleep
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:620 (sofia/external/135790*14152225555) State Change CS_HANGUP -> CS_REPORTING
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:585 (sofia/external/135790*14152225555) Running State Change CS_REPORTING (Cur 2 Tot 33)
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:936 (sofia/external/135790*14152225555) State REPORTING
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:174 sofia/external/135790*14152225555 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:936 (sofia/external/135790*14152225555) State REPORTING going to sleep
2020-10-07 00:36:29.682231 [DEBUG] switch_core_state_machine.c:611 (sofia/external/135790*14152225555) State Change CS_REPORTING -> CS_DESTROY
2020-10-07 00:36:29.682231 [DEBUG] switch_core_session.c:1726 Session 33 (sofia/external/135790*14152225555) Locked, Waiting on external entities
2020-10-07 00:36:29.702224 [DEBUG] switch_ivr_originate.c:3949 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2020-10-07 00:36:29.702224 [NOTICE] switch_core_session.c:1744 Session 33 (sofia/external/135790*14152225555) Ended
2020-10-07 00:36:29.702224 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/135790*14152225555 [CS_DESTROY]
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:739 (sofia/external/135790*14152225555) Running State Change CS_DESTROY (Cur 1 Tot 33)
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:749 (sofia/external/135790*14152225555) State DESTROY
2020-10-07 00:36:29.702224 [DEBUG] mod_sofia.c:365 sofia/external/135790*14152225555 SOFIA DESTROY
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:181 sofia/external/135790*14152225555 Standard DESTROY
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:749 (sofia/external/135790*14152225555) State DESTROY going to sleep
2020-10-07 00:36:29.702224 [INFO] mod_dptools.c:3631 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
2020-10-07 00:36:29.702224 [NOTICE] switch_core_state_machine.c:386 sofia/internal/8201@my.pbxdomain.net has executed the last dialplan instruction, hanging up.
2020-10-07 00:36:29.702224 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/internal/8201@my.pbxdomain.net [CS_EXECUTE] [NORMAL_CLEARING]
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/8201@my.pbxdomain.net) State EXECUTE going to sleep
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_HANGUP (Cur 1 Tot 33)
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/8201@my.pbxdomain.net) Callstate Change RINGING -> HANGUP
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/8201@my.pbxdomain.net) State HANGUP
2020-10-07 00:36:29.702224 [DEBUG] mod_sofia.c:454 sofia/internal/8201@my.pbxdomain.net Overriding SIP cause 480 with 503 from the other leg
2020-10-07 00:36:29.702224 [DEBUG] mod_sofia.c:460 Channel sofia/internal/8201@my.pbxdomain.net hanging up, cause: NORMAL_CLEARING
2020-10-07 00:36:29.702224 [DEBUG] mod_sofia.c:605 Responding to INVITE with: 503
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:60 sofia/internal/8201@my.pbxdomain.net Standard HANGUP, cause: NORMAL_CLEARING
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/8201@my.pbxdomain.net) State HANGUP going to sleep
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/8201@my.pbxdomain.net) State Change CS_HANGUP -> CS_REPORTING
send 927 bytes to tcp/[111.22.33.4]:29833 at 00:37:06.784943:
------------------------------------------------------------------------
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/TCP 10.10.10.20:29833;rport=29833;branch=z9hG4bKPjeebfcabb4e5b46cf943d2ff9b0f00ce5;alias;received=111.22.33.4
Max-Forwards: 70
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>;tag=Stvg2c2cmtSXF
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24483 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: "4152225555" <sip:4152225555@my.pbxdomain.net>;party=calling;privacy=off;screen=no

2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_REPORTING (Cur 1 Tot 33)
2020-10-07 00:36:29.702224 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/8201@my.pbxdomain.net) State REPORTING
recv 396 bytes from tcp/[111.22.33.4]:29833 at 00:37:06.823443:
------------------------------------------------------------------------
ACK sip:14152225555@my.pbxdomain.net SIP/2.0
Via: SIP/2.0/TCP 10.10.10.20:29833;rport;branch=z9hG4bKPjeebfcabb4e5b46cf943d2ff9b0f00ce5;alias
Max-Forwards: 70
From: "Ext 8201" <sip:8201@my.pbxdomain.net>;tag=7b0c28ec60fd491f989518ca1cf99c87
To: <sip:14152225555@my.pbxdomain.net>;tag=Stvg2c2cmtSXF
Call-ID: c0a0c33f9b994254ab0b6c319a60d3df
CSeq: 24483 ACK
Content-Length:  0

2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:174 sofia/internal/8201@my.pbxdomain.net Standard REPORTING, cause: NORMAL_CLEARING
2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/8201@my.pbxdomain.net) State REPORTING going to sleep
2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/8201@my.pbxdomain.net) State Change CS_REPORTING -> CS_DESTROY
2020-10-07 00:36:29.762228 [DEBUG] switch_core_session.c:1726 Session 32 (sofia/internal/8201@my.pbxdomain.net) Locked, Waiting on external entities
2020-10-07 00:36:29.762228 [NOTICE] switch_core_session.c:1744 Session 32 (sofia/internal/8201@my.pbxdomain.net) Ended
2020-10-07 00:36:29.762228 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/8201@my.pbxdomain.net [CS_DESTROY]
2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/8201@my.pbxdomain.net) Running State Change CS_DESTROY (Cur 0 Tot 33)
2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/8201@my.pbxdomain.net) State DESTROY
2020-10-07 00:36:29.762228 [DEBUG] mod_sofia.c:365 sofia/internal/8201@my.pbxdomain.net SOFIA DESTROY
2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:181 sofia/internal/8201@my.pbxdomain.net Standard DESTROY
2020-10-07 00:36:29.762228 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/8201@my.pbxdomain.net) State DESTROY going to sleep
recv 783 bytes from udp/[98.152.188.246]:1495 at 00:37:07.565976:

DigitalDaz · Oct 8, 2020

Repeat the same exercise as above with sofia loglevel all 9

It will be big

Msquared · Oct 8, 2020

DigitalDaz said:
Repeat the same exercise as above with sofia loglevel all 9

It will be big

Thank you for the reply! That did provide a better insight (and a ton of noise).

So if I am reading this correctly, DNS is being resolved, NAPTR SRV records are being returned but it's not able to reach the SIP provider?

I did a dig on that record from my server and found the IP it resolves to. If I build a Gateway in Fusion using the IP everything works (not an ideal fix).

I found an old ticket from 2013 where using DNS with FlowRoute would fail, but this was reported as a bug and was resolved. (ref: http://freeswitch-users.2379917.n2....on-outbound-proxy-FQDN-failing-td7594880.html ) Adding {sip_gethostbyname=true} to the bridge did not work for me either.

Code:

sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f3aa8003e90, NAPTR, "us-west-wa.sip.flowroute.com.") called
sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f3aa8003e90, NAPTR, "us-west-wa.sip.flowroute.com.") returned 3 entries
nta.c:10404 outgoing_query_naptr() nta: for "us-west-wa.sip.flowroute.com" query "us-west-wa.sip.flowroute.com" NAPTR (cached)
nta.c:10471 outgoing_answer_naptr() nta: us-west-wa.sip.flowroute.com. IN NAPTR 100 10 "s" "SIP+D2U" "" _sip._udp.us-west-wa.sip.flowroute.com.
nta.c:10471 outgoing_answer_naptr() nta: us-west-wa.sip.flowroute.com. IN NAPTR 102 20 "s" "SIP+D2T" "" _sip._tcp.us-west-wa.sip.flowroute.com.                                                                                         (out of order)
nta.c:10471 outgoing_answer_naptr() nta: us-west-wa.sip.flowroute.com. IN NAPTR 103 20 "s" "SIPS+D2T" "" _sips._tcp.us-west-wa.sip.flowroute.co                                                                                        m. (out of order)
sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f3aa8003e90, SRV, "_sip._udp.us-west-wa.sip.flowroute.com.") called
sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f3aa8003e90, SRV, "_sip._udp.us-west-wa.sip.flowroute.com.") returned 1 entries
nta.c:10604 outgoing_query_srv() nta: for "us-west-wa.sip.flowroute.com" query "_sip._udp.us-west-wa.sip.flowroute.com." SRV (cached)
nua_session.c:4143 signal_call_state_change() nua(0x7f3aa03d46f0): call state changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f3aa8004480, [0x7f3ad4064bd8], [0x7f3ad4064be0], [(nil)]) called
nua_stack.c:269 nua_stack_event() nua(0x7f3aa03d46f0): event i_state INVITE sent
nua_stack.c:271 nua_stack_event() nua(0x7f3aa03d46f0): event r_invite 503 DNS Error
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_session.c:4143 signal_call_state_change() nua(0x7f3aa03d46f0): call state changed: calling -> init
nua_stack.c:271 nua_stack_event() nua(0x7f3aa03d46f0): event i_state 503 DNS Error
nua_stack.c:271 nua_stack_event() nua(0x7f3aa03d46f0): event i_terminated 503 DNS Error

Msquared · Oct 9, 2020

Changing the Outbound Routes Dialplan bridge to add @us-west-wa.sip.flowroute.com:5060 seems to fix the issue (the port # on the end is what worked for me).

My old bridge looked like:
sofia/gateway/flowroute/123456*1$1

I changed it to look like:
sofia/gateway/flowroute/123456*1$1@us-west-wa.sip.flowroute.com:5060

Outbound calls seem to be working again. I still don't know why the old dial plan bridge has worked for the past year and now the hostname and port need to be added, but it is working. I've also learned to always use multiple SIP accounts & routes as a fail safe

.

( ref: http://freeswitch-users.2379917.n2.nabble.com/Authorizations-when-using-DNS-SRV-bug-td3480547.html)

Search

Search

SOLVED Outbound Calls Suddenly Failing With Cause 41 Normal Temporary Failure Error

Msquared

New Member

DigitalDaz

Administrator

Msquared

New Member

Attachments

Msquared

New Member

DigitalDaz

Administrator

Msquared

New Member

Msquared

New Member