[Freeswitch-users] Locked, Waiting on external entities

Geoff Mina gmina at connectfirst.com
Sat Feb 10 21:43:40 UTC 2018


Greetings,
I was wondering if anyone knows what the "Locked, Waiting on external
entities" message indicates.

First, I am using a FusionPBX GUI to play with some basic PBX
functionality.  The flow of my call is an XML transfer from a public to a
private context.  Enabling trusted outside party to dial extensions
directly on the Freeswitch host.

The call comes in on the external SIP profile and transfers to the internal
profile.  The softphone rings and I hit "decline" which sends back a 486
Busy Here to FS.  Freeswitch then hangs in a "Waiting on external entities"
state until a timeout occurs at which point the inbound call is finally
sent to voicemail after an internal 408 timeout.

This is FS 1.6.20 installed from Yum on a CentOS7 box.  Attached is the
full log file with SIP tracing enabled.  Here is the relevant snippet where
the switch is just sitting for 16 seconds doing nothing.

2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:610
(sofia/internal/113 at 161.97.193.191:51392) State Change CS_REPORTING ->
CS_DESTROY
*2018-02-10 21:27:11.132820 [DEBUG] switch_core_session.c:1665 Session 87
(sofia/internal/113 at 161.97.193.191:51392 <http://113@161.97.193.191:51392>)
Locked, Waiting on external entities*
*2018-02-10 21:27:40.952819 [DEBUG] sofia.c:7084 Channel
sofia/internal/113 at 161.97.193.191:51094 <http://113@161.97.193.191:51094>
entering state [terminated][408]*
2018-02-10 21:27:40.952819 [NOTICE] sofia.c:8273 Hangup sofia/internal/
113 at 161.97.193.191:51094 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]

Just a point in the right direction as to what may cause this would be
appreciated.

Thanks,
Geoff
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20180210/e36fb15d/attachment-0001.html>
-------------- next part --------------
recv 1102 bytes from udp/[174.37.181.39]:5060 at 21:27:08.881601:
   ------------------------------------------------------------------------
   INVITE sip:113 at c00-pbx.somedomain.com SIP/2.0
   Record-Route: <sip:174.37.181.39;lr;ftag=as54b5500e>
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK1375.9bd5a993470896a1e4e38b2bff4f084b.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK61968ea6;rport=5060
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>
   Contact: <sip:5555551212 at 52.11.183.123>
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 102 INVITE
   User-Agent: G-Tel v1.0
   Max-Forwards: 69
   Remote-Party-ID: "5555551212" <sip:5555551212 at somedomain.com>;privacy=off;screen=no
   Date: Sat, 10 Feb 2018 21:27:08 GMT
   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
   Supported: replaces
   P-Account-ID: 99990009
   Content-Type: application/sdp
   Content-Length: 289

   v=0
   o=root 27044 27044 IN IP4 52.11.183.123
   s=session
   c=IN IP4 52.11.183.123
   t=0 0
   m=audio 10466 RTP/AVP 18 0 101
   a=rtpmap:18 G729/8000
   a=fmtp:18 annexb=no
   a=rtpmap:0 PCMU/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=silenceSupp:off - - - -
   a=ptime:20
   a=sendrecv
   ------------------------------------------------------------------------
send 457 bytes to udp/[174.37.181.39]:5060 at 21:27:08.881851:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK1375.9bd5a993470896a1e4e38b2bff4f084b.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK61968ea6;rport=5060
   Record-Route: <sip:174.37.181.39;lr;ftag=as54b5500e>
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 102 INVITE
   User-Agent: FreeSWITCH
   Content-Length: 0

   ------------------------------------------------------------------------
2018-02-10 21:27:08.872820 [NOTICE] switch_channel.c:1104 New Channel sofia/external/5555551212 at somedomain.com [2640726c-0ea9-11e8-ad64-53f0f54925c8]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_NEW (Cur 1 Tot 84)
2018-02-10 21:27:08.872820 [DEBUG] sofia.c:9873 sofia/external/5555551212 at somedomain.com receiving invite from 174.37.181.39:5060 version: 1.6.20  64bit
2018-02-10 21:27:08.872820 [DEBUG] sofia.c:7084 Channel sofia/external/5555551212 at somedomain.com entering state [received][100]
2018-02-10 21:27:08.872820 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=root 27044 27044 IN IP4 52.11.183.123
s=session
c=IN IP4 52.11.183.123
t=0 0
m=audio 10466 RTP/AVP 18 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20

2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:115:32000:20:48000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:107:16000:20:32000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101 at 8000
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external/5555551212 at somedomain.com PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2018-02-10 21:27:08.872820 [DEBUG] switch_core_codec.c:111 sofia/external/5555551212 at somedomain.com Original read codec set to PCMU:0
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101 at 8000
2018-02-10 21:27:08.872820 [DEBUG] switch_core_media.c:4767 sofia/external/5555551212 at somedomain.com Set 2833 dtmf send payload to 101 recv payload to 101
2018-02-10 21:27:08.872820 [DEBUG] sofia.c:7507 (sofia/external/5555551212 at somedomain.com) State Change CS_NEW -> CS_INIT
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:603 (sofia/external/5555551212 at somedomain.com) State NEW
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_INIT (Cur 1 Tot 84)
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:627 (sofia/external/5555551212 at somedomain.com) State INIT
2018-02-10 21:27:08.872820 [DEBUG] mod_sofia.c:90 sofia/external/5555551212 at somedomain.com SOFIA INIT
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:40 sofia/external/5555551212 at somedomain.com Standard INIT
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:48 (sofia/external/5555551212 at somedomain.com) State Change CS_INIT -> CS_ROUTING
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:627 (sofia/external/5555551212 at somedomain.com) State INIT going to sleep
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_ROUTING (Cur 1 Tot 84)
2018-02-10 21:27:08.872820 [DEBUG] switch_channel.c:2249 (sofia/external/5555551212 at somedomain.com) Callstate Change DOWN -> RINGING
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:643 (sofia/external/5555551212 at somedomain.com) State ROUTING
2018-02-10 21:27:08.872820 [DEBUG] mod_sofia.c:143 sofia/external/5555551212 at somedomain.com SOFIA ROUTING
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:236 sofia/external/5555551212 at somedomain.com Standard ROUTING
2018-02-10 21:27:08.872820 [INFO] mod_dialplan_xml.c:637 Processing 5555551212 <5555551212>->113 in context public
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->1000] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [1000] destination_number(113) =~ /^(1000)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->112] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [112] destination_number(113) =~ /^(112)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->113] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [113] destination_number(113) =~ /^(113)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action set(call_direction=inbound) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(call_direction=inbound)
2018-02-10 21:27:08.872820 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [call_direction]=[inbound]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(domain_uuid=1f2f7a81-1b0f-4d02-87e4-a316e8187e81) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(domain_uuid=1f2f7a81-1b0f-4d02-87e4-a316e8187e81)
2018-02-10 21:27:08.872820 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [domain_uuid]=[1f2f7a81-1b0f-4d02-87e4-a316e8187e81]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(domain_name=c00-pbx.somedomain.com) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(domain_name=c00-pbx.somedomain.com)
2018-02-10 21:27:08.872820 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [domain_name]=[c00-pbx.somedomain.com]
Dialplan: sofia/external/5555551212 at somedomain.com Action transfer(113 XML c00-pbx.somedomain.com)
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->114] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [114] destination_number(113) =~ /^(114)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->115] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [115] destination_number(113) =~ /^(115)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->116] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [116] destination_number(113) =~ /^(116)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->118] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [118] destination_number(113) =~ /^(118)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->119] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [119] destination_number(113) =~ /^(119)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [public->2000] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [2000] destination_number(113) =~ /^(2000)$/ break=on-false
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:286 (sofia/external/5555551212 at somedomain.com) State Change CS_ROUTING -> CS_EXECUTE
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:643 (sofia/external/5555551212 at somedomain.com) State ROUTING going to sleep
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_EXECUTE (Cur 1 Tot 84)
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:650 (sofia/external/5555551212 at somedomain.com) State EXECUTE
2018-02-10 21:27:08.872820 [DEBUG] mod_sofia.c:198 sofia/external/5555551212 at somedomain.com SOFIA EXECUTE
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:328 sofia/external/5555551212 at somedomain.com Standard EXECUTE
EXECUTE sofia/external/5555551212 at somedomain.com transfer(113 XML c00-pbx.somedomain.com)
2018-02-10 21:27:08.872820 [DEBUG] switch_ivr.c:2165 (sofia/external/5555551212 at somedomain.com) State Change CS_EXECUTE -> CS_ROUTING
2018-02-10 21:27:08.872820 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/5555551212 at somedomain.com to XML[113 at c00-pbx.somedomain.com]
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:650 (sofia/external/5555551212 at somedomain.com) State EXECUTE going to sleep
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_ROUTING (Cur 1 Tot 84)
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:643 (sofia/external/5555551212 at somedomain.com) State ROUTING
2018-02-10 21:27:08.872820 [DEBUG] mod_sofia.c:143 sofia/external/5555551212 at somedomain.com SOFIA ROUTING
2018-02-10 21:27:08.872820 [DEBUG] switch_core_state_machine.c:236 sofia/external/5555551212 at somedomain.com Standard ROUTING
2018-02-10 21:27:08.872820 [INFO] mod_dialplan_xml.c:637 Processing 5555551212 <5555551212>->113 in context c00-pbx.somedomain.com
2018-02-10 21:27:08.892884 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f6e24050320 Connected.
2018-02-10 21:27:08.892884 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f6e24050320 released.
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->user_exists] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(user_exists=true)
2018-02-10 21:27:08.892884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [user_exists]=[true]
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(extension_uuid=667ba7bb-fdd8-4a4c-9ac6-11643eaac636)
2018-02-10 21:27:08.892884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [extension_uuid]=[667ba7bb-fdd8-4a4c-9ac6-11643eaac636]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(hold_music=local_stream://default)
2018-02-10 21:27:08.892884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [hold_music]=[local_stream://default]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_all_enabled=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_all_enabled]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_all_destination=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_all_destination]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_busy_enabled=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_busy_enabled]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_busy_destination=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_busy_destination]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_no_answer_enabled=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_no_answer_enabled]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_no_answer_destination=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_user_not_registered_enabled=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_user_not_registered_enabled]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(forward_user_not_registered_destination=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(do_not_disturb=)
2018-02-10 21:27:08.912879 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [do_not_disturb]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(call_timeout=30)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [call_timeout]=[30]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(missed_call_app=)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [missed_call_app]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(missed_call_data=)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [missed_call_data]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(toll_allow=)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [toll_allow]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(call_screen_enabled=false)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [call_screen_enabled]=[false]
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->call-direction] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->variables] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/external/5555551212 at somedomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->user_record] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com set(user_record=)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [user_record]=[UNDEF]
Dialplan: sofia/external/5555551212 at somedomain.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2018-02-10 21:27:08.932884 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f6e24050320 Connected.
2018-02-10 21:27:08.932884 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f6e24050320 released.
EXECUTE sofia/external/5555551212 at somedomain.com set(from_user_exists=false)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [from_user_exists]=[false]
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->redial] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [redial] destination_number(113) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/external/5555551212 at somedomain.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->speed_dial] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [speed_dial] destination_number(113) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->sipious.011.9-17d] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [sipious.011.9-17d] destination_number(113) =~ /^(011\d{9,17})$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->sipious.10d] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [sipious.10d] destination_number(113) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->sipious.11d] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [sipious.11d] destination_number(113) =~ /^\+?(\d{11})$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->agent_status] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [agent_status] destination_number(113) =~ /^\*22$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->agent_status_id] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [agent_status_id] destination_number(113) =~ /^\*23$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->group-intercept] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [group-intercept] destination_number(113) =~ /^\*8$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->page-extension] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [page-extension] destination_number(113) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->call_privacy] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call_privacy] destination_number(113) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->call_return] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call_return] destination_number(113) =~ /^\*69$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->extension_queue] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [extension_queue] destination_number(113) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->intercept-ext] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [intercept-ext] destination_number(113) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->intercept-ext-polycom] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [intercept-ext-polycom] destination_number(113) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->dx] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [dx] destination_number(113) =~ /^dx$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->att_xfer] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [att_xfer] destination_number(113) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->extension-to-voicemail] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [extension-to-voicemail] username(5555551212) =~ /^5555551212$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [extension-to-voicemail] destination_number(113) =~ /^5555551212$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->send_to_voicemail] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [send_to_voicemail] destination_number(113) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->vmain] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [vmain] destination_number(113) =~ /^vmain$|^\*4000$|^\*98$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->xfer_vm] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [xfer_vm] destination_number(113) =~ /^xfer_vm$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->is_transfer] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [is_transfer] destination_number(113) =~ /^is_transfer$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->vmain_user] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [vmain_user] destination_number(113) =~ /^\*97$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->Dev-Conference] continue=
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [Dev-Conference] destination_number(113) =~ /^1000$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->Exec-Conference] continue=
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [Exec-Conference] destination_number(113) =~ /^2000$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->cf] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [cf] destination_number(113) =~ /^cf$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->delay_echo] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [delay_echo] destination_number(113) =~ /^\*9195$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->echo] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [echo] destination_number(113) =~ /^\*9196$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->is_zrtp_secure] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com ANTI-Action eval(not_secure)
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->milliwatt] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [milliwatt] destination_number(113) =~ /^\*9197$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->is_secure] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->tone_stream] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [tone_stream] destination_number(113) =~ /^\*9198$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->hold_music] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [hold_music] destination_number(113) =~ /^\*9664$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->recordings] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [recordings] destination_number(113) =~ /^\*(732)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->directory] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [directory] destination_number(113) =~ /^\*411$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->wake-up] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [wake-up] destination_number(113) =~ /^\*(925)$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->valet_park] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [valet_park] destination_number(113) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [valet_park] destination_number(113) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=never
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [valet_park] destination_number(113) =~ /^(park\+)?(\*59[0-9][0-9])$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->operator] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [operator] destination_number(113) =~ /^0$|^operator$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->operator-forward] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [operator-forward] destination_number(113) =~ /^\*000$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->do-not-disturb] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [do-not-disturb] destination_number(113) =~ /^\*77$/ break=on-true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [do-not-disturb] destination_number(113) =~ /^\*78$|\*363$/ break=on-true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [do-not-disturb] destination_number(113) =~ /^\*79$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->call-forward] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call-forward] destination_number(113) =~ /^\*72$/ break=on-true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call-forward] destination_number(113) =~ /^\*73$/ break=on-true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call-forward] destination_number(113) =~ /^\*74$/ break=on-true
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->call forward all] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [call forward all] ${user_exists}(true) =~ /^true/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call forward all] ${forward_all_enabled}() =~ /^true/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->follow-me] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [follow-me] destination_number(113) =~ /^\*21$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->clear_sip_auto_answer] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->talking clock date and time] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [talking clock date and time] destination_number(113) =~ /^\*9172$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->talking clock time] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [talking clock time] destination_number(113) =~ /^\*9170$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->talking clock date] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [talking clock date] destination_number(113) =~ /^\*9171$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->call_screen] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->local_extension] continue=true
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action export(dialed_extension=${destination_number}) INLINE
EXECUTE sofia/external/5555551212 at somedomain.com export(dialed_extension=113)
2018-02-10 21:27:08.932884 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[113]
Dialplan: sofia/external/5555551212 at somedomain.com Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [local_extension] () =~ // break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action set(hangup_after_bridge=true)
Dialplan: sofia/external/5555551212 at somedomain.com Action set(continue_on_fail=true)
Dialplan: sofia/external/5555551212 at somedomain.com Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/external/5555551212 at somedomain.com Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/external/5555551212 at somedomain.com Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/external/5555551212 at somedomain.com Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/external/5555551212 at somedomain.com Action export(domain_name=${domain_name})
Dialplan: sofia/external/5555551212 at somedomain.com Action bridge({originate_timeout=40}user/${destination_number}@${domain_name})
Dialplan: sofia/external/5555551212 at somedomain.com parsing [c00-pbx.somedomain.com->voicemail] continue=false
Dialplan: sofia/external/5555551212 at somedomain.com Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/external/5555551212 at somedomain.com Action answer()
Dialplan: sofia/external/5555551212 at somedomain.com Action sleep(1000)
Dialplan: sofia/external/5555551212 at somedomain.com Action set(voicemail_action=save)
Dialplan: sofia/external/5555551212 at somedomain.com Action set(voicemail_id=${destination_number})
Dialplan: sofia/external/5555551212 at somedomain.com Action set(voicemail_profile=default)
Dialplan: sofia/external/5555551212 at somedomain.com Action lua(app.lua voicemail)
2018-02-10 21:27:08.932884 [DEBUG] switch_core_state_machine.c:286 (sofia/external/5555551212 at somedomain.com) State Change CS_ROUTING -> CS_EXECUTE
2018-02-10 21:27:08.932884 [DEBUG] switch_core_state_machine.c:643 (sofia/external/5555551212 at somedomain.com) State ROUTING going to sleep
2018-02-10 21:27:08.932884 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_EXECUTE (Cur 1 Tot 84)
2018-02-10 21:27:08.932884 [DEBUG] switch_core_state_machine.c:650 (sofia/external/5555551212 at somedomain.com) State EXECUTE
2018-02-10 21:27:08.932884 [DEBUG] mod_sofia.c:198 sofia/external/5555551212 at somedomain.com SOFIA EXECUTE
2018-02-10 21:27:08.932884 [DEBUG] switch_core_state_machine.c:328 sofia/external/5555551212 at somedomain.com Standard EXECUTE
EXECUTE sofia/external/5555551212 at somedomain.com export(origination_callee_id_name=113)
2018-02-10 21:27:08.932884 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[113]
EXECUTE sofia/external/5555551212 at somedomain.com set(RFC2822_DATE=Sat, 10 Feb 2018 21:27:08 +0000)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [RFC2822_DATE]=[Sat, 10 Feb 2018 21:27:08 +0000]
EXECUTE sofia/external/5555551212 at somedomain.com hash(insert/c00-pbx.somedomain.com-last_dial/5555551212/113)
EXECUTE sofia/external/5555551212 at somedomain.com eval(not_secure)
EXECUTE sofia/external/5555551212 at somedomain.com limit(hash c00-pbx.somedomain.com 113  )
2018-02-10 21:27:08.932884 [DEBUG] switch_limit.c:126 incr called: c00-pbx.somedomain.com_113 max:-1, interval:0
2018-02-10 21:27:08.932884 [DEBUG] mod_hash.c:194 Usage for c00-pbx.somedomain.com_113 is now 1
EXECUTE sofia/external/5555551212 at somedomain.com set(hangup_after_bridge=true)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [hangup_after_bridge]=[true]
EXECUTE sofia/external/5555551212 at somedomain.com set(continue_on_fail=true)
2018-02-10 21:27:08.932884 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [continue_on_fail]=[true]
EXECUTE sofia/external/5555551212 at somedomain.com hash(insert/c00-pbx.somedomain.com-call_return/113/5555551212)
EXECUTE sofia/external/5555551212 at somedomain.com hash(insert/c00-pbx.somedomain.com-last_dial_ext/113/2640726c-0ea9-11e8-ad64-53f0f54925c8)
EXECUTE sofia/external/5555551212 at somedomain.com set(called_party_call_group=)
2018-02-10 21:27:08.952886 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [called_party_call_group]=[UNDEF]
EXECUTE sofia/external/5555551212 at somedomain.com hash(insert/c00-pbx.somedomain.com-last_dial//2640726c-0ea9-11e8-ad64-53f0f54925c8)
EXECUTE sofia/external/5555551212 at somedomain.com export(domain_name=c00-pbx.somedomain.com)
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=[c00-pbx.somedomain.com]
EXECUTE sofia/external/5555551212 at somedomain.com bridge({originate_timeout=40}user/113 at c00-pbx.somedomain.com)
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1250 sofia/external/5555551212 at somedomain.com EXPORTING[export_vars] [dialed_extension]=[113] to event
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1250 sofia/external/5555551212 at somedomain.com EXPORTING[export_vars] [origination_callee_id_name]=[113] to event
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1250 sofia/external/5555551212 at somedomain.com EXPORTING[export_vars] [domain_name]=[c00-pbx.somedomain.com] to event
2018-02-10 21:27:08.952886 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1250 sofia/external/5555551212 at somedomain.com EXPORTING[export_vars] [dialed_extension]=[113] to event
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1250 sofia/external/5555551212 at somedomain.com EXPORTING[export_vars] [origination_callee_id_name]=[113] to event
2018-02-10 21:27:08.952886 [DEBUG] switch_channel.c:1250 sofia/external/5555551212 at somedomain.com EXPORTING[export_vars] [domain_name]=[c00-pbx.somedomain.com] to event
2018-02-10 21:27:08.952886 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-02-10 21:27:08.952886 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/113 at 161.97.193.191:51094 [264c07a8-0ea9-11e8-ad90-53f0f54925c8]
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:4819 (sofia/internal/113 at 161.97.193.191:51094) State Change CS_NEW -> CS_INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51094) Running State Change CS_INIT (Cur 2 Tot 85)
2018-02-10 21:27:08.952886 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/113 at 161.97.193.191:51337 [264c1838-0ea9-11e8-ad95-53f0f54925c8]
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:4819 (sofia/internal/113 at 161.97.193.191:51337) State Change CS_NEW -> CS_INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/113 at 161.97.193.191:51094) State INIT
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:90 sofia/internal/113 at 161.97.193.191:51094 SOFIA INIT
2018-02-10 21:27:08.952886 [DEBUG] sofia_glue.c:1264 sip:113 at 161.97.193.191:51094;rinstance=630f1da21036c7ab;transport=tcp Setting proxy route to sofia/internal/113 at 161.97.193.191:51094
2018-02-10 21:27:08.952886 [DEBUG] sofia_glue.c:1295 sofia/internal/113 at 161.97.193.191:51094 sending invite version: 1.6.20  64bit
Local SDP:
v=0
o=FreeSWITCH 1518274048 1518274049 IN IP4 52.25.47.217
s=FreeSWITCH
c=IN IP4 52.25.47.217
t=0 0
m=audio 23980 RTP/AVP 0 102 103 9 8 3 101 13 104 105 106 107
a=rtpmap:0 PCMU/8000
a=rtpmap:102 G7221/32000
a=fmtp:102 bitrate=48000
a=rtpmap:103 G7221/16000
a=fmtp:103 bitrate=32000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:104 telephone-event/32000
a=fmtp:104 0-16
a=rtpmap:106 telephone-event/16000
a=fmtp:106 0-16
a=rtpmap:13 CN/8000
a=rtpmap:105 CN/32000
a=rtpmap:107 CN/16000
a=ptime:20
a=sendrecv

2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:40 sofia/internal/113 at 161.97.193.191:51094 Standard INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/113 at 161.97.193.191:51094) State Change CS_INIT -> CS_ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/113 at 161.97.193.191:51094) State INIT going to sleep
2018-02-10 21:27:08.952886 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/113 at 161.97.193.191:51392 [264c28be-0ea9-11e8-ad9a-53f0f54925c8]
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:4819 (sofia/internal/113 at 161.97.193.191:51392) State Change CS_NEW -> CS_INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51337) Running State Change CS_INIT (Cur 4 Tot 87)
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51094) Running State Change CS_ROUTING (Cur 4 Tot 87)
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/113 at 161.97.193.191:51094) State ROUTING
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:143 sofia/internal/113 at 161.97.193.191:51094 SOFIA ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/113 at 161.97.193.191:51094) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/113 at 161.97.193.191:51094) State ROUTING going to sleep
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/113 at 161.97.193.191:51337) State INIT
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:90 sofia/internal/113 at 161.97.193.191:51337 SOFIA INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51094) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 87)
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51392) Running State Change CS_INIT (Cur 4 Tot 87)
2018-02-10 21:27:08.952886 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51094 entering state [calling][0]
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/113 at 161.97.193.191:51094) State CONSUME_MEDIA
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/113 at 161.97.193.191:51094) State CONSUME_MEDIA going to sleep
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/113 at 161.97.193.191:51392) State INIT
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:90 sofia/internal/113 at 161.97.193.191:51392 SOFIA INIT
2018-02-10 21:27:08.952886 [DEBUG] sofia_glue.c:1264 sip:113 at 161.97.193.191:51337;rinstance=3baeca2d38d0500d;transport=tcp Setting proxy route to sofia/internal/113 at 161.97.193.191:51337
2018-02-10 21:27:08.952886 [DEBUG] sofia_glue.c:1295 sofia/internal/113 at 161.97.193.191:51337 sending invite version: 1.6.20  64bit
Local SDP:
v=0
o=FreeSWITCH 1518268504 1518268505 IN IP4 52.25.47.217
s=FreeSWITCH
c=IN IP4 52.25.47.217
t=0 0
m=audio 29524 RTP/AVP 0 102 103 9 8 3 101 13 104 105 106 107
a=rtpmap:0 PCMU/8000
a=rtpmap:102 G7221/32000
a=fmtp:102 bitrate=48000
a=rtpmap:103 G7221/16000
a=fmtp:103 bitrate=32000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:104 telephone-event/32000
a=fmtp:104 0-16
a=rtpmap:106 telephone-event/16000
a=fmtp:106 0-16
a=rtpmap:13 CN/8000
a=rtpmap:105 CN/32000
a=rtpmap:107 CN/16000
a=ptime:20
a=sendrecv

2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:40 sofia/internal/113 at 161.97.193.191:51337 Standard INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/113 at 161.97.193.191:51337) State Change CS_INIT -> CS_ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/113 at 161.97.193.191:51337) State INIT going to sleep
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51337) Running State Change CS_ROUTING (Cur 4 Tot 87)
2018-02-10 21:27:08.952886 [DEBUG] sofia_glue.c:1264 sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp Setting proxy route to sofia/internal/113 at 161.97.193.191:51392
2018-02-10 21:27:08.952886 [DEBUG] sofia_glue.c:1295 sofia/internal/113 at 161.97.193.191:51392 sending invite version: 1.6.20  64bit
Local SDP:
v=0
o=FreeSWITCH 1518274964 1518274965 IN IP4 52.25.47.217
s=FreeSWITCH
c=IN IP4 52.25.47.217
t=0 0
m=audio 23064 RTP/AVP 0 102 103 9 8 3 101 13 104 105 106 107
a=rtpmap:0 PCMU/8000
a=rtpmap:102 G7221/32000
a=fmtp:102 bitrate=48000
a=rtpmap:103 G7221/16000
a=fmtp:103 bitrate=32000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:104 telephone-event/32000
a=fmtp:104 0-16
a=rtpmap:106 telephone-event/16000
a=fmtp:106 0-16
a=rtpmap:13 CN/8000
a=rtpmap:105 CN/32000
a=rtpmap:107 CN/16000
a=ptime:20
a=sendrecv

2018-02-10 21:27:08.952886 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51337 entering state [calling][0]
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/113 at 161.97.193.191:51337) State ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:40 sofia/internal/113 at 161.97.193.191:51392 Standard INIT
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/113 at 161.97.193.191:51392) State Change CS_INIT -> CS_ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/113 at 161.97.193.191:51392) State INIT going to sleep
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:143 sofia/internal/113 at 161.97.193.191:51337 SOFIA ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/113 at 161.97.193.191:51337) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/113 at 161.97.193.191:51337) State ROUTING going to sleep
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51337) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 87)
send 1715 bytes to tcp/[161.97.193.191]:51392 at 21:27:08.959845:
   ------------------------------------------------------------------------
   INVITE sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp SIP/2.0
   Via: SIP/2.0/TCP 52.25.47.217:5080;rport;branch=z9hG4bK9U4H9c0yB0eme
   Route: <sip:113 at 161.97.193.191:51392>;rinstance=3baeca2d38d0500d;transport=tcp
   Max-Forwards: 67
   From: "5555551212" <sip:5555551212 at c00-pbx.somedomain.com>;tag=Bct4yrNeQ5gmK
   To: <sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp>
   Call-ID: fdaa910f-894b-1236-0aa7-02a1db012a3a
   CSeq: 118812950 INVITE
   Contact: <sip:mod_sofia at 52.25.47.217:5080;transport=tcp>
   User-Agent: FreeSWITCH
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, path, replaces
   Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 595
   P-Account-ID: 99990009
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51392) Running State Change CS_ROUTING (Cur 4 Tot 87)
   X-FS-Support: update_display,send_info
   Remote-Party-ID: "5555551212" <sip:5555551212 at c00-pbx.somedomain.com>;party=calling;screen=no;privacy=off

   v=0
   o=FreeSWITCH 1518274964 1518274965 IN IP4 52.25.47.217
   s=FreeSWITCH
   c=IN IP4 52.25.47.217
   t=0 0
   m=audio 23064 RTP/AVP 0 102 103 9 8 3 101 13 104 105 106 107
   a=rtpmap:0 PCMU/8000
   a=rtpmap:102 G7221/32000
   a=fmtp:102 bitrate=48000
   a=rtpmap:103 G7221/16000
   a=fmtp:103 bitrate=32000
   a=rtpmap:9 G722/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:3 GSM/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=rtpmap:13 CN/8000
   a=rtpmap:104 telephone-event/32000
   a=fmtp:104 0-16
   a=rtpmap:105 CN/32000
   a=rtpmap:106 telephone-event/16000
   a=fmtp:106 0-16
   a=rtpmap:107 CN/16000
   a=ptime:20
   ------------------------------------------------------------------------
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/113 at 161.97.193.191:51337) State CONSUME_MEDIA
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/113 at 161.97.193.191:51337) State CONSUME_MEDIA going to sleep
2018-02-10 21:27:08.952886 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51392 entering state [calling][0]
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/113 at 161.97.193.191:51392) State ROUTING
2018-02-10 21:27:08.952886 [DEBUG] mod_sofia.c:143 sofia/internal/113 at 161.97.193.191:51392 SOFIA ROUTING
2018-02-10 21:27:08.952886 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/113 at 161.97.193.191:51392) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/113 at 161.97.193.191:51392) State ROUTING going to sleep
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51392) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 87)
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/113 at 161.97.193.191:51392) State CONSUME_MEDIA
2018-02-10 21:27:08.952886 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/113 at 161.97.193.191:51392) State CONSUME_MEDIA going to sleep
recv 336 bytes from tcp/[161.97.193.191]:51392 at 21:27:09.537722:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/TCP 52.25.47.217:5080;rport=5080;branch=z9hG4bK9U4H9c0yB0eme
   To: <sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp>
   From: "5555551212" <sip:5555551212 at c00-pbx.somedomain.com>;tag=Bct4yrNeQ5gmK
   Call-ID: fdaa910f-894b-1236-0aa7-02a1db012a3a
   CSeq: 118812950 INVITE
   Content-Length: 0

   ------------------------------------------------------------------------
recv 519 bytes from tcp/[161.97.193.191]:51392 at 21:27:09.618735:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/TCP 52.25.47.217:5080;rport=5080;branch=z9hG4bK9U4H9c0yB0eme
   Contact: <sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp>
   To: "Geoffrey Mina"<sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp>;tag=e91e9a69
   From: "5555551212" <sip:5555551212 at c00-pbx.somedomain.com>;tag=Bct4yrNeQ5gmK
   Call-ID: fdaa910f-894b-1236-0aa7-02a1db012a3a
   CSeq: 118812950 INVITE
   User-Agent: Bria 5 release 5.0.3 stamp 88307
   Allow-Events: talk, hold
   Content-Length: 0

   ------------------------------------------------------------------------
2018-02-10 21:27:09.612821 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51392 entering state [proceeding][180]
2018-02-10 21:27:09.612821 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/113 at 161.97.193.191:51392!
2018-02-10 21:27:09.612821 [DEBUG] switch_channel.c:3346 (sofia/internal/113 at 161.97.193.191:51392) Callstate Change DOWN -> RINGING
2018-02-10 21:27:09.612821 [INFO] switch_ivr_originate.c:1215 Sending early media
2018-02-10 21:27:09.612821 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external/5555551212 at somedomain.com] 10.10.1.160 port 25762 -> 52.11.183.123 port 10466 codec: 0 ms: 20
2018-02-10 21:27:09.612821 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
2018-02-10 21:27:09.612821 [DEBUG] switch_core_media.c:7180 sofia/external/5555551212 at somedomain.com Set 2833 dtmf send payload to 101
2018-02-10 21:27:09.612821 [DEBUG] switch_core_media.c:7187 sofia/external/5555551212 at somedomain.com Set 2833 dtmf receive payload to 101
2018-02-10 21:27:09.612821 [DEBUG] switch_core_media.c:7210 sofia/external/5555551212 at somedomain.com Set rtp dtmf delay to 40
2018-02-10 21:27:09.612821 [DEBUG] mod_sofia.c:2364 Ring SDP:
v=0
o=FreeSWITCH 1518272267 1518272268 IN IP4 52.25.47.217
s=FreeSWITCH
c=IN IP4 52.25.47.217
t=0 0
m=audio 25762 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2018-02-10 21:27:09.612821 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/external/5555551212 at somedomain.com!
2018-02-10 21:27:09.612821 [DEBUG] switch_channel.c:3474 (sofia/external/5555551212 at somedomain.com) Callstate Change RINGING -> EARLY
2018-02-10 21:27:09.612821 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16 at 8000hz 1 channel 20ms
2018-02-10 21:27:09.612821 [DEBUG] switch_core_codec.c:223 sofia/external/5555551212 at somedomain.com Push codec L16:100
2018-02-10 21:27:09.612821 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)]
send 1098 bytes to udp/[174.37.181.39]:5060 at 21:27:09.624226:
   ------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK1375.9bd5a993470896a1e4e38b2bff4f084b.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK61968ea6;rport=5060
   Record-Route: <sip:174.37.181.39;lr;ftag=as54b5500e>
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>;tag=Z3SgKX3H5Fc7a
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 102 INVITE
   Contact: <sip:113 at 52.25.47.217:5060;transport=udp>
   User-Agent: FreeSWITCH
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
   Supported: timer, path, replaces
   Allow-Events: talk, hold, conference, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 220
   Remote-Party-ID: "113" <sip:113 at 174.37.181.39>;party=calling;privacy=off;screen=no

   v=0
   o=FreeSWITCH 1518272267 1518272268 IN IP4 52.25.47.217
   s=FreeSWITCH
   c=IN IP4 52.25.47.217
   t=0 0
   m=audio 25762 RTP/AVP 0 101
   a=rtpmap:0 PCMU/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2018-02-10 21:27:09.632878 [DEBUG] sofia.c:7084 Channel sofia/external/5555551212 at somedomain.com entering state [early][183]
recv 398 bytes from tcp/[161.97.193.191]:51392 at 21:27:11.147223:
   ------------------------------------------------------------------------
   SIP/2.0 486 Busy Here
   Via: SIP/2.0/TCP 52.25.47.217:5080;rport=5080;branch=z9hG4bK9U4H9c0yB0eme
   To: <sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp>;tag=e91e9a69
   From: "5555551212" <sip:5555551212 at c00-pbx.somedomain.com>;tag=Bct4yrNeQ5gmK
   Call-ID: fdaa910f-894b-1236-0aa7-02a1db012a3a
   CSeq: 118812950 INVITE
   User-Agent: Bria 5 release 5.0.3 stamp 88307
   Content-Length: 0

   ------------------------------------------------------------------------
send 502 bytes to tcp/[161.97.193.191]:51392 at 21:27:11.147324:
   ------------------------------------------------------------------------
   ACK sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp SIP/2.0
   Via: SIP/2.0/TCP 52.25.47.217:5080;rport;branch=z9hG4bK9U4H9c0yB0eme
   Route: <sip:113 at 161.97.193.191:51392>;rinstance=3baeca2d38d0500d;transport=tcp
   Max-Forwards: 67
   From: "5555551212" <sip:5555551212 at c00-pbx.somedomain.com>;tag=Bct4yrNeQ5gmK
   To: <sip:113 at 161.97.193.191:51392;rinstance=3baeca2d38d0500d;transport=tcp>;tag=e91e9a69
   Call-ID: fdaa910f-894b-1236-0aa7-02a1db012a3a
   CSeq: 118812950 ACK
   Content-Length: 0

   ------------------------------------------------------------------------
2018-02-10 21:27:11.132820 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51392 entering state [terminated][486]
2018-02-10 21:27:11.132820 [NOTICE] sofia.c:8273 Hangup sofia/internal/113 at 161.97.193.191:51392 [CS_CONSUME_MEDIA] [USER_BUSY]
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51392) Running State Change CS_HANGUP (Cur 4 Tot 87)
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/113 at 161.97.193.191:51392) Callstate Change RINGING -> HANGUP
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/113 at 161.97.193.191:51392) State HANGUP
2018-02-10 21:27:11.132820 [DEBUG] mod_sofia.c:438 Channel sofia/internal/113 at 161.97.193.191:51392 hanging up, cause: USER_BUSY
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:60 sofia/internal/113 at 161.97.193.191:51392 Standard HANGUP, cause: USER_BUSY
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/113 at 161.97.193.191:51392) State HANGUP going to sleep
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/113 at 161.97.193.191:51392) State Change CS_HANGUP -> CS_REPORTING
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51392) Running State Change CS_REPORTING (Cur 4 Tot 87)
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/113 at 161.97.193.191:51392) State REPORTING
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:174 sofia/internal/113 at 161.97.193.191:51392 Standard REPORTING, cause: USER_BUSY
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/113 at 161.97.193.191:51392) State REPORTING going to sleep
2018-02-10 21:27:11.132820 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/113 at 161.97.193.191:51392) State Change CS_REPORTING -> CS_DESTROY
2018-02-10 21:27:11.132820 [DEBUG] switch_core_session.c:1665 Session 87 (sofia/internal/113 at 161.97.193.191:51392) Locked, Waiting on external entities
2018-02-10 21:27:40.952819 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51094 entering state [terminated][408]
2018-02-10 21:27:40.952819 [NOTICE] sofia.c:8273 Hangup sofia/internal/113 at 161.97.193.191:51094 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51094) Running State Change CS_HANGUP (Cur 4 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/113 at 161.97.193.191:51094) Callstate Change DOWN -> HANGUP
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/113 at 161.97.193.191:51094) State HANGUP
2018-02-10 21:27:40.952819 [DEBUG] mod_sofia.c:438 Channel sofia/internal/113 at 161.97.193.191:51094 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:60 sofia/internal/113 at 161.97.193.191:51094 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/113 at 161.97.193.191:51094) State HANGUP going to sleep
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/113 at 161.97.193.191:51094) State Change CS_HANGUP -> CS_REPORTING
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51094) Running State Change CS_REPORTING (Cur 4 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/113 at 161.97.193.191:51094) State REPORTING
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:174 sofia/internal/113 at 161.97.193.191:51094 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/113 at 161.97.193.191:51094) State REPORTING going to sleep
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/113 at 161.97.193.191:51094) State Change CS_REPORTING -> CS_DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_session.c:1665 Session 85 (sofia/internal/113 at 161.97.193.191:51094) Locked, Waiting on external entities
2018-02-10 21:27:40.952819 [DEBUG] sofia.c:7084 Channel sofia/internal/113 at 161.97.193.191:51337 entering state [terminated][408]
2018-02-10 21:27:40.952819 [NOTICE] sofia.c:8273 Hangup sofia/internal/113 at 161.97.193.191:51337 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51337) Running State Change CS_HANGUP (Cur 4 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/113 at 161.97.193.191:51337) Callstate Change DOWN -> HANGUP
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/113 at 161.97.193.191:51337) State HANGUP
2018-02-10 21:27:40.952819 [DEBUG] mod_sofia.c:438 Channel sofia/internal/113 at 161.97.193.191:51337 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:60 sofia/internal/113 at 161.97.193.191:51337 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/113 at 161.97.193.191:51337) State HANGUP going to sleep
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/113 at 161.97.193.191:51337) State Change CS_HANGUP -> CS_REPORTING
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/113 at 161.97.193.191:51337) Running State Change CS_REPORTING (Cur 4 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/113 at 161.97.193.191:51337) State REPORTING
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:174 sofia/internal/113 at 161.97.193.191:51337 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/113 at 161.97.193.191:51337) State REPORTING going to sleep
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/113 at 161.97.193.191:51337) State Change CS_REPORTING -> CS_DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_session.c:1665 Session 86 (sofia/internal/113 at 161.97.193.191:51337) Locked, Waiting on external entities
2018-02-10 21:27:40.952819 [DEBUG] switch_core_codec.c:248 sofia/external/5555551212 at somedomain.com Restore previous codec PCMU:0.
2018-02-10 21:27:40.952819 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2018-02-10 21:27:40.952819 [NOTICE] switch_core_session.c:1683 Session 85 (sofia/internal/113 at 161.97.193.191:51094) Ended
2018-02-10 21:27:40.952819 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/113 at 161.97.193.191:51094 [CS_DESTROY]
2018-02-10 21:27:40.952819 [NOTICE] switch_core_session.c:1683 Session 86 (sofia/internal/113 at 161.97.193.191:51337) Ended
2018-02-10 21:27:40.952819 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/113 at 161.97.193.191:51337 [CS_DESTROY]
2018-02-10 21:27:40.952819 [NOTICE] switch_core_session.c:1683 Session 87 (sofia/internal/113 at 161.97.193.191:51392) Ended
2018-02-10 21:27:40.952819 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/113 at 161.97.193.191:51392 [CS_DESTROY]
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/113 at 161.97.193.191:51337) Running State Change CS_DESTROY (Cur 1 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/113 at 161.97.193.191:51094) Running State Change CS_DESTROY (Cur 1 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/113 at 161.97.193.191:51337) State DESTROY
2018-02-10 21:27:40.952819 [DEBUG] mod_sofia.c:343 sofia/internal/113 at 161.97.193.191:51337 SOFIA DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:181 sofia/internal/113 at 161.97.193.191:51337 Standard DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/113 at 161.97.193.191:51337) State DESTROY going to sleep
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/113 at 161.97.193.191:51094) State DESTROY
2018-02-10 21:27:40.952819 [DEBUG] mod_sofia.c:343 sofia/internal/113 at 161.97.193.191:51094 SOFIA DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:181 sofia/internal/113 at 161.97.193.191:51094 Standard DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/113 at 161.97.193.191:51094) State DESTROY going to sleep
2018-02-10 21:27:40.952819 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [RECOVERY_ON_TIMER_EXPIRE]
2018-02-10 21:27:40.952819 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/113 at 161.97.193.191:51392) Running State Change CS_DESTROY (Cur 1 Tot 87)
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/113 at 161.97.193.191:51392) State DESTROY
2018-02-10 21:27:40.952819 [DEBUG] mod_sofia.c:343 sofia/internal/113 at 161.97.193.191:51392 SOFIA DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:181 sofia/internal/113 at 161.97.193.191:51392 Standard DESTROY
2018-02-10 21:27:40.952819 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/113 at 161.97.193.191:51392) State DESTROY going to sleep
2018-02-10 21:27:40.952819 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: RECOVERY_ON_TIMER_EXPIRE
EXECUTE sofia/external/5555551212 at somedomain.com answer()
2018-02-10 21:27:40.952819 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external/5555551212 at somedomain.com.
2018-02-10 21:27:40.952819 [DEBUG] mod_sofia.c:850 Local SDP sofia/external/5555551212 at somedomain.com:
v=0
o=FreeSWITCH 1518272267 1518272269 IN IP4 52.25.47.217
s=FreeSWITCH
c=IN IP4 52.25.47.217
t=0 0
m=audio 25762 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2018-02-10 21:27:40.952819 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/5555551212 at somedomain.com] has been answered
send 1059 bytes to udp/[174.37.181.39]:5060 at 21:27:40.963158:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK1375.9bd5a993470896a1e4e38b2bff4f084b.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK61968ea6;rport=5060
   Record-Route: <sip:174.37.181.39;lr;ftag=as54b5500e>
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>;tag=Z3SgKX3H5Fc7a
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 102 INVITE
   Contact: <sip:113 at 52.25.47.217:5060;transport=udp>
   User-Agent: FreeSWITCH
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
   Supported: timer, path, replaces
   Allow-Events: talk, hold, conference, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 220
   Remote-Party-ID: "113" <sip:113 at 174.37.181.39>;party=calling;privacy=off;screen=no

   v=0
   o=FreeSWITCH 1518272267 1518272268 IN IP4 52.25.47.217
   s=FreeSWITCH
   c=IN IP4 52.25.47.217
   t=0 0
   m=audio 25762 RTP/AVP 0 101
   a=rtpmap:0 PCMU/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2018-02-10 21:27:40.952819 [DEBUG] switch_channel.c:3773 (sofia/external/5555551212 at somedomain.com) Callstate Change EARLY -> ACTIVE
2018-02-10 21:27:40.952819 [DEBUG] sofia.c:7084 Channel sofia/external/5555551212 at somedomain.com entering state [completed][200]
EXECUTE sofia/external/5555551212 at somedomain.com sleep(1000)
recv 597 bytes from udp/[174.37.181.39]:5060 at 21:27:40.981008:
   ------------------------------------------------------------------------
   ACK sip:113 at 52.25.47.217:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK1375.1a5a8dc16597fd9a60f6e198c0e8018e.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK6e94b06c;rport=5060
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>;tag=Z3SgKX3H5Fc7a
   Contact: <sip:5555551212 at 52.11.183.123>
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 102 ACK
   User-Agent: G-Tel v1.0
   Max-Forwards: 69
   Remote-Party-ID: "5555551212" <sip:5555551212 at somedomain.com>;privacy=off;screen=no
   Content-Length: 0

   ------------------------------------------------------------------------
2018-02-10 21:27:40.972822 [DEBUG] sofia.c:7084 Channel sofia/external/5555551212 at somedomain.com entering state [ready][200]
2018-02-10 21:27:41.052818 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
EXECUTE sofia/external/5555551212 at somedomain.com set(voicemail_action=save)
2018-02-10 21:27:41.952820 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [voicemail_action]=[save]
EXECUTE sofia/external/5555551212 at somedomain.com set(voicemail_id=113)
2018-02-10 21:27:41.952820 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [voicemail_id]=[113]
EXECUTE sofia/external/5555551212 at somedomain.com set(voicemail_profile=default)
2018-02-10 21:27:41.952820 [DEBUG] mod_dptools.c:1548 SET sofia/external/5555551212 at somedomain.com [voicemail_profile]=[default]
EXECUTE sofia/external/5555551212 at somedomain.com lua(app.lua voicemail)
2018-02-10 21:27:41.952820 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f6e24050320 Connected.
EXECUTE sofia/external/5555551212 at somedomain.com unbind_meta_app()
2018-02-10 21:27:41.952820 [INFO] switch_ivr_async.c:4072 UnBound A-Leg: ALL
2018-02-10 21:27:41.952820 [DEBUG] switch_cpp.cpp:745 CoreSession::setVariable('playback_terminators', '#')
EXECUTE sofia/external/5555551212 at somedomain.com playback(silence_stream://200)
2018-02-10 21:27:41.972822 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16 at 8000hz 1 channels 20ms
2018-02-10 21:27:42.152818 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://200
2018-02-10 21:27:42.152818 [DEBUG] switch_core_file.c:342 File /var/lib/freeswitch/storage/voicemail/default/c00-pbx.somedomain.com/113/greeting_1.wav sample rate 16000 doesn't match requested rate 8000
2018-02-10 21:27:42.152818 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16 at 8000hz 1 channels 20ms
recv 620 bytes from udp/[174.37.181.39]:5060 at 21:27:45.144259:
   ------------------------------------------------------------------------
   BYE sip:113 at 52.25.47.217:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK2375.b9d921e7f38da83d8c7dcaa0c03cab38.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK3af11d1c;rport=5060
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>;tag=Z3SgKX3H5Fc7a
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 103 BYE
   User-Agent: G-Tel v1.0
   Max-Forwards: 69
   Remote-Party-ID: "5555551212" <sip:5555551212 at somedomain.com>;privacy=off;screen=no
   X-Asterisk-HangupCause: Unknown
   X-Asterisk-HangupCauseCode: 0
   Content-Length: 0

   ------------------------------------------------------------------------
2018-02-10 21:27:45.152820 [NOTICE] sofia.c:1012 Hangup sofia/external/5555551212 at somedomain.com [CS_EXECUTE] [NORMAL_CLEARING]
2018-02-10 21:27:45.152820 [DEBUG] mod_hash.c:297 Usage for c00-pbx.somedomain.com_113 is now 0
2018-02-10 21:27:45.152820 [DEBUG] switch_ivr_play_say.c:1942 done playing file /var/lib/freeswitch/storage/voicemail/default/c00-pbx.somedomain.com/113/greeting_1.wav
send 538 bytes to udp/[174.37.181.39]:5060 at 21:27:45.162662:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 174.37.181.39;branch=z9hG4bK2375.b9d921e7f38da83d8c7dcaa0c03cab38.0
   Via: SIP/2.0/UDP 52.11.183.123:5060;branch=z9hG4bK3af11d1c;rport=5060
   From: "5555551212" <sip:5555551212 at somedomain.com>;tag=as54b5500e
   To: <sip:113 at 174.37.181.39:5060>;tag=Z3SgKX3H5Fc7a
   Call-ID: 4f43cc193246d9f07d56ccf80ecb9d09 at somedomain.com
   CSeq: 103 BYE
   User-Agent: FreeSWITCH
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
   Supported: timer, path, replaces
   Content-Length: 0

   ------------------------------------------------------------------------
2018-02-10 21:27:45.152820 [NOTICE] switch_cpp.cpp:1365 [voicemail]
2018-02-10 21:27:45.152820 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f6e24050320 released.
2018-02-10 21:27:45.152820 [DEBUG] switch_cpp.cpp:1112 sofia/external/5555551212 at somedomain.com destroy/unlink session from object
2018-02-10 21:27:45.152820 [DEBUG] switch_core_session.c:2815 sofia/external/5555551212 at somedomain.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:650 (sofia/external/5555551212 at somedomain.com) State EXECUTE going to sleep
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_HANGUP (Cur 1 Tot 87)
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:850 (sofia/external/5555551212 at somedomain.com) Callstate Change ACTIVE -> HANGUP
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:852 (sofia/external/5555551212 at somedomain.com) State HANGUP
2018-02-10 21:27:45.152820 [DEBUG] mod_sofia.c:432 sofia/external/5555551212 at somedomain.com Overriding SIP cause 480 with 408 from the other leg
2018-02-10 21:27:45.152820 [DEBUG] mod_sofia.c:438 Channel sofia/external/5555551212 at somedomain.com hanging up, cause: NORMAL_CLEARING
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:60 sofia/external/5555551212 at somedomain.com Standard HANGUP, cause: NORMAL_CLEARING
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:852 (sofia/external/5555551212 at somedomain.com) State HANGUP going to sleep
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:619 (sofia/external/5555551212 at somedomain.com) State Change CS_HANGUP -> CS_REPORTING
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:584 (sofia/external/5555551212 at somedomain.com) Running State Change CS_REPORTING (Cur 1 Tot 87)
2018-02-10 21:27:45.152820 [DEBUG] switch_core_state_machine.c:938 (sofia/external/5555551212 at somedomain.com) State REPORTING
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:174 sofia/external/5555551212 at somedomain.com Standard REPORTING, cause: NORMAL_CLEARING
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:938 (sofia/external/5555551212 at somedomain.com) State REPORTING going to sleep
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:610 (sofia/external/5555551212 at somedomain.com) State Change CS_REPORTING -> CS_DESTROY
2018-02-10 21:27:45.172877 [DEBUG] switch_core_session.c:1665 Session 84 (sofia/external/5555551212 at somedomain.com) Locked, Waiting on external entities
2018-02-10 21:27:45.172877 [NOTICE] switch_core_session.c:1683 Session 84 (sofia/external/5555551212 at somedomain.com) Ended
2018-02-10 21:27:45.172877 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/5555551212 at somedomain.com [CS_DESTROY]
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:741 (sofia/external/5555551212 at somedomain.com) Running State Change CS_DESTROY (Cur 0 Tot 87)
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:751 (sofia/external/5555551212 at somedomain.com) State DESTROY
2018-02-10 21:27:45.172877 [DEBUG] mod_sofia.c:343 sofia/external/5555551212 at somedomain.com SOFIA DESTROY
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:181 sofia/external/5555551212 at somedomain.com Standard DESTROY
2018-02-10 21:27:45.172877 [DEBUG] switch_core_state_machine.c:751 (sofia/external/5555551212 at somedomain.com) State DESTROY going to sleep
freeswitch at c00-pbx.somedomain.com>


More information about the FreeSWITCH-users mailing list