Skip to content

Instantly share code, notes, and snippets.

@mm0ntg0m

mm0ntg0m/debug.log

Created November 30, 2016 20:14
Show Gist options
  • Save mm0ntg0m/3619cf9a9b4abadf6b35590596437407 to your computer and use it in GitHub Desktop.
Save mm0ntg0m/3619cf9a9b4abadf6b35590596437407 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
debug.log
1508032762-0-504819810@DID_PROVIDER recv 1120 bytes from udp/[KAZOO_IP]:5060 at 13:13:57.735928:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER INVITE sip:+15555556900@KAZOO_IP:5060 SIP/2.0
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER Contact: <sip:15554446313@DID_PROVIDER_SIP_IP:5060>
1508032762-0-504819810@DID_PROVIDER Supported: timer
1508032762-0-504819810@DID_PROVIDER Session-Expires: 1800;refresher=uac
1508032762-0-504819810@DID_PROVIDER Min-SE: 90
1508032762-0-504819810@DID_PROVIDER P-Asserted-Identity: <sip:+15554446313@4.55.9.227:5060>
1508032762-0-504819810@DID_PROVIDER Max-Forwards: 50
1508032762-0-504819810@DID_PROVIDER Content-Type: application/sdp
1508032762-0-504819810@DID_PROVIDER Content-Length: 298
1508032762-0-504819810@DID_PROVIDER X-AUTH-IP: DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER X-AUTH-PORT: 5060
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER v=0
1508032762-0-504819810@DID_PROVIDER o=Sansay-VSXi 188 1 IN IP4 DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER s=Session Controller
1508032762-0-504819810@DID_PROVIDER c=IN IP4 4.55.9.194
1508032762-0-504819810@DID_PROVIDER t=0 0
1508032762-0-504819810@DID_PROVIDER m=audio 13400 RTP/AVP 0 8 18 101
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:8 PCMA/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:18 G729/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:18 annexb=no
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-15
1508032762-0-504819810@DID_PROVIDER a=sendrecv
1508032762-0-504819810@DID_PROVIDER a=maxptime:20
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER send 545 bytes to udp/[KAZOO_IP]:5060 at 13:13:57.736302:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER SIP/2.0 100 Trying
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [NOTICE] switch_channel.c:1075 New Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [1508032762-0-504819810@DID_PROVIDER]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_NEW
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:9053 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP receiving invite from KAZOO_IP:5060 version: 1.4.23 64bit
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [received][100]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:6668 Remote SDP:
1508032762-0-504819810@DID_PROVIDER v=0^M
1508032762-0-504819810@DID_PROVIDER o=Sansay-VSXi 188 1 IN IP4 DID_PROVIDER_SIP_IP^M
1508032762-0-504819810@DID_PROVIDER s=Session Controller^M
1508032762-0-504819810@DID_PROVIDER c=IN IP4 4.55.9.194^M
1508032762-0-504819810@DID_PROVIDER t=0 0^M
1508032762-0-504819810@DID_PROVIDER m=audio 13400 RTP/AVP 0 8 18 101^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:8 PCMA/8000^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:18 G729/8000^M
1508032762-0-504819810@DID_PROVIDER a=fmtp:18 annexb=no^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000^M
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-15^M
1508032762-0-504819810@DID_PROVIDER a=maxptime:20^M
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:6935 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_NEW -> CS_INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State NEW
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_INIT -> CS_ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State INIT going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_channel.c:2204 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change DOWN -> RINGING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:166 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [INFO] mod_dialplan_xml.c:635 Processing 15554446313 <+15554446313>->+15555556900 in context context_2
2016-11-30 13:14:35.819567 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Account-Trunk-Usage=0/0/1/0;ecallmgr_Reseller-Trunk-Usage=0/0/-1/0)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP parsing [context_2->park] continue=false
1508032762-0-504819810@DID_PROVIDER |--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE
1508032762-0-504819810@DID_PROVIDER |--- Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
1508032762-0-504819810@DID_PROVIDER |--- Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action export(ecallmgr_Bridge-ID=${UUID}) INLINE
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP export(ecallmgr_Bridge-ID=1508032762-0-504819810@DID_PROVIDER)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[1508032762-0-504819810@DID_PROVIDER]
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Absolute Condition [park]
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action log(NOTICE log|${uuid}|ecallmgr@KZ.DOMAIN.com won call control)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action export(ecallmgr_Ecallmgr-Node=ecallmgr@KZ.DOMAIN.com)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(transfer_ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action ring_ready()
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Caller-Privacy-Number=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Caller-Privacy-Name=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ignore_display_updates=true)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Inception=+15555556900@KAZOO_IP)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_CNAM-From-Cache=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(effective_caller_id_name=CALLER)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Channel-Authorized=true)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Global-Resource=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Reseller-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Account-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action park()
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:216 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_ROUTING -> CS_EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State ROUTING going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:258 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard EXECUTE
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP log(NOTICE log|1508032762-0-504819810@DID_PROVIDER|ecallmgr@KZ.DOMAIN.com won call control)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [NOTICE] mod_dptools.c:1692 log|1508032762-0-504819810@DID_PROVIDER|ecallmgr@KZ.DOMAIN.com won call control
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP export(ecallmgr_Ecallmgr-Node=ecallmgr@KZ.DOMAIN.com)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr@KZ.DOMAIN.com]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ringback]=[%(2000,4000,440,480)]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(transfer_ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [transfer_ringback]=[%(2000,4000,440,480)]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP ring_ready()
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [NOTICE] mod_sofia.c:2105 Ring-Ready sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP!
1508032762-0-504819810@DID_PROVIDER send 1032 bytes to udp/[KAZOO_IP]:5060 at 13:13:58.151678:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_session.c:913 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER SIP/2.0 180 Ringing
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.01508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [NOTICE] mod_dptools.c:1016 Ring Ready sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP!
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER Contact: <sip:+15555556900@FREESWITCH_IP:11000;transport=udp>
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Accept: application/sdp
1508032762-0-504819810@DID_PROVIDER Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1508032762-0-504819810@DID_PROVIDER Supported: path, replaces
1508032762-0-504819810@DID_PROVIDER Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER P-Asserted-Identity: "+15555556900" <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [early][180]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Fetch-ID]=[da097270-b6fe-11e6-add7-b1e6e2c88a05]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Caller-Privacy-Number=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Caller-Privacy-Number]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Caller-Privacy-Name=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Caller-Privacy-Name]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ignore_display_updates=true)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ignore_display_updates]=[true]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Inception=+15555556900@KAZOO_IP)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Inception]=[+15555556900@KAZOO_IP]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_CNAM-From-Cache=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_CNAM-From-Cache]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(effective_caller_id_name=CALLER)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [effective_caller_id_name]=[CALLER]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Channel-Authorized=true)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Channel-Authorized]=[true]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Global-Resource=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Global-Resource]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Reseller-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Reseller-Billing]=[flat_rate]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Reseller-ID]=[03496e31004899b670a0d23fa72db096]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Account-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Account-Billing]=[flat_rate]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Account-ID]=[d19d11f7ce18c797263fe4c4a0cdba49]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP park()
2016-11-30 13:14:36.039533 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Rate-NoCharge-Time=0;ecallmgr_Pvt-Cost=0;ecallmgr_Base-Cost=0;ecallmgr_Rate-Name=Inbound US-1;ecallmgr_Surcharge=0;ecallmgr_Rate-Minimum=6;ecallmgr_Rate-Increment=6;ecallmgr_Rate=240)
2016-11-30 13:14:36.039533 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49;ecallmgr_Account-Billing=flat_rate;ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096;ecallmgr_Reseller-Billing=flat_rate;ecallmgr_Channel-Authorized=true;effective_caller_id_name=CALLER;ecallmgr_Inception=+15555556900@KAZOO_IP;ignore_display_updates=true;ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05;ecallmgr_Application-Node=whistle_apps@KZ.DOMAIN.com;ecallmgr_Application-Name=callflow)
2016-11-30 13:14:36.059549 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05;ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49;ignore_display_updates=true;ecallmgr_Inception=+15555556900@KAZOO_IP;effective_caller_id_name=CALLER;ecallmgr_Account-Billing=flat_rate;ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096;ecallmgr_Reseller-Billing=flat_rate;ecallmgr_Channel-Authorized=true;ecallmgr_Application-Node=whistle_apps@KZ.DOMAIN.com;ecallmgr_Application-Name=callflow;effective_caller_id_number=+15554446313)
2016-11-30 13:14:36.259564 [NOTICE] kazoo_node.c:285 log|1508032762-0-504819810@DID_PROVIDER|executing answer
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_session.c:1197 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_ivr.c:616 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Command Execute answer()
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP answer()
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:115:32000:20:48000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:107:16000:20:32000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[SPEEX:99:8000:20:24600:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3595 Set telephone-event payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:2506 Set Codec sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP PCMU/8000 20 ms 160 samples 64000 bits 1 channels
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Original read codec set to PCMU:0
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3942 Set 2833 dtmf send/recv payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:5178 AUDIO RTP [sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP] FREESWITCH_IP port 19684 -> 4.55.9.194 port 13400 codec: 0 ms: 20
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 160 bytes per 20ms
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_media.c:5476 Set 2833 dtmf send payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_media.c:5482 Set 2833 dtmf receive payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_media.c:5504 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Set rtp dtmf delay to 40
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP!
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_channel.c:3419 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change RINGING -> EARLY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] mod_sofia.c:782 Local SDP sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP:
1508032762-0-504819810@DID_PROVIDER v=0
1508032762-0-504819810@DID_PROVIDER o=FreeSWITCH 1480491992 1480491993 IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER s=FreeSWITCH
1508032762-0-504819810@DID_PROVIDER c=IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER t=0 0
1508032762-0-504819810@DID_PROVIDER m=audio 19684 RTP/AVP 0 101
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-16
1508032762-0-504819810@DID_PROVIDER a=ptime:20
1508032762-0-504819810@DID_PROVIDER a=sendrecv
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_session.c:913 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [NOTICE] mod_dptools.c:1300 Channel [sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP] has been answered
1508032762-0-504819810@DID_PROVIDER send 1289 bytes to udp/[KAZOO_IP]:5060 at 13:13:58.402977:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER SIP/2.0 200 OK
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER Contact: <sip:+15555556900@FREESWITCH_IP:11000;transport=udp>
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1508032762-0-504819810@DID_PROVIDER Supported: path, replaces
1508032762-0-504819810@DID_PROVIDER Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1508032762-0-504819810@DID_PROVIDER Content-Type: application/sdp
1508032762-0-504819810@DID_PROVIDER Content-Disposition: session
1508032762-0-504819810@DID_PROVIDER Content-Length: 224
1508032762-0-504819810@DID_PROVIDER P-Asserted-Identity: "+15555556900" <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER v=0
1508032762-0-504819810@DID_PROVIDER o=FreeSWITCH 1480491992 1480491993 IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER s=FreeSWITCH
1508032762-0-504819810@DID_PROVIDER c=IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER t=0 0
1508032762-0-504819810@DID_PROVIDER m=audio 19684 RTP/AVP 0 101
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-16
1508032762-0-504819810@DID_PROVIDER a=ptime:20
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_channel.c:3711 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change EARLY -> ACTIVE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [completed][200]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_ivr.c:963 Codec Activated L16@8000hz 1 channels 20ms
1508032762-0-504819810@DID_PROVIDER recv 499 bytes from udp/[KAZOO_IP]:5060 at 13:13:58.445280:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER ACK sip:+15555556900@FREESWITCH_IP:11000;transport=udp SIP/2.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.e441f2e2c64d926816fb591d4b2b0a6a.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887-200
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 ACK
1508032762-0-504819810@DID_PROVIDER Max-Forwards: 50
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER X-AUTH-IP: DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER X-AUTH-PORT: 5060
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [ready][200]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.360070 [DEBUG] switch_rtp.c:5894 Correct ip/port confirmed.
1508032762-0-504819810@DID_PROVIDER recv 495 bytes from udp/[KAZOO_IP]:5060 at 13:14:10.462248:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER BYE sip:+15555556900@FREESWITCH_IP:11000;transport=udp SIP/2.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKbc4a.06cf506f369ee389507e72c44ca37e87.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK2sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 2 BYE
1508032762-0-504819810@DID_PROVIDER Max-Forwards: 50
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER X-AUTH-IP: DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER X-AUTH-PORT: 5060
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.339580 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.339580 [NOTICE] sofia.c:952 Hangup sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [CS_EXECUTE] [NORMAL_CLEARING]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_channel.c:3242 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [KILL]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER send 543 bytes to udp/[KAZOO_IP]:5060 at 13:14:10.481654:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER SIP/2.0 200 OK
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKbc4a.06cf506f369ee389507e72c44ca37e87.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK2sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 2 BYE
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1508032762-0-504819810@DID_PROVIDER Supported: path, replaces
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:2767 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State EXECUTE going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_HANGUP
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:735 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change ACTIVE -> HANGUP
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State HANGUP
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP hanging up, cause: NORMAL_CLEARING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard HANGUP, cause: NORMAL_CLEARING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State HANGUP going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_HANGUP -> CS_REPORTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_REPORTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State REPORTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard REPORTING, cause: NORMAL_CLEARING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State REPORTING going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:498 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_REPORTING -> CS_DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1624 Session 4933 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Locked, Waiting on external entities
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [NOTICE] switch_core_session.c:1642 Session 4933 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Ended
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [NOTICE] switch_core_session.c:1646 Close Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [CS_DESTROY]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:626 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:111 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State DESTROY going to sleep
1508032762-0-504819810@DID_PROVIDER recv 1120 bytes from udp/[KAZOO_IP]:5060 at 13:13:57.735928:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER INVITE sip:+15555556900@KAZOO_IP:5060 SIP/2.0
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER Contact: <sip:15554446313@DID_PROVIDER_SIP_IP:5060>
1508032762-0-504819810@DID_PROVIDER Supported: timer
1508032762-0-504819810@DID_PROVIDER Session-Expires: 1800;refresher=uac
1508032762-0-504819810@DID_PROVIDER Min-SE: 90
1508032762-0-504819810@DID_PROVIDER P-Asserted-Identity: <sip:+15554446313@4.55.9.227:5060>
1508032762-0-504819810@DID_PROVIDER Max-Forwards: 50
1508032762-0-504819810@DID_PROVIDER Content-Type: application/sdp
1508032762-0-504819810@DID_PROVIDER Content-Length: 298
1508032762-0-504819810@DID_PROVIDER X-AUTH-IP: DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER X-AUTH-PORT: 5060
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER v=0
1508032762-0-504819810@DID_PROVIDER o=Sansay-VSXi 188 1 IN IP4 DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER s=Session Controller
1508032762-0-504819810@DID_PROVIDER c=IN IP4 4.55.9.194
1508032762-0-504819810@DID_PROVIDER t=0 0
1508032762-0-504819810@DID_PROVIDER m=audio 13400 RTP/AVP 0 8 18 101
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:8 PCMA/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:18 G729/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:18 annexb=no
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-15
1508032762-0-504819810@DID_PROVIDER a=sendrecv
1508032762-0-504819810@DID_PROVIDER a=maxptime:20
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER send 545 bytes to udp/[KAZOO_IP]:5060 at 13:13:57.736302:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER SIP/2.0 100 Trying
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [NOTICE] switch_channel.c:1075 New Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [1508032762-0-504819810@DID_PROVIDER]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_NEW
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:9053 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP receiving invite from KAZOO_IP:5060 version: 1.4.23 64bit
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [received][100]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:6668 Remote SDP:
1508032762-0-504819810@DID_PROVIDER v=0^M
1508032762-0-504819810@DID_PROVIDER o=Sansay-VSXi 188 1 IN IP4 DID_PROVIDER_SIP_IP^M
1508032762-0-504819810@DID_PROVIDER s=Session Controller^M
1508032762-0-504819810@DID_PROVIDER c=IN IP4 4.55.9.194^M
1508032762-0-504819810@DID_PROVIDER t=0 0^M
1508032762-0-504819810@DID_PROVIDER m=audio 13400 RTP/AVP 0 8 18 101^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:8 PCMA/8000^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:18 G729/8000^M
1508032762-0-504819810@DID_PROVIDER a=fmtp:18 annexb=no^M
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000^M
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-15^M
1508032762-0-504819810@DID_PROVIDER a=maxptime:20^M
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] sofia.c:6935 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_NEW -> CS_INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State NEW
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard INIT
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_INIT -> CS_ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State INIT going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_channel.c:2204 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change DOWN -> RINGING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [DEBUG] switch_core_state_machine.c:166 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard ROUTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:35.599608 [INFO] mod_dialplan_xml.c:635 Processing 15554446313 <+15554446313>->+15555556900 in context context_2
2016-11-30 13:14:35.819567 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Account-Trunk-Usage=0/0/1/0;ecallmgr_Reseller-Trunk-Usage=0/0/-1/0)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP parsing [context_2->park] continue=false
1508032762-0-504819810@DID_PROVIDER |--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE
1508032762-0-504819810@DID_PROVIDER |--- Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
1508032762-0-504819810@DID_PROVIDER |--- Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action export(ecallmgr_Bridge-ID=${UUID}) INLINE
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP export(ecallmgr_Bridge-ID=1508032762-0-504819810@DID_PROVIDER)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[1508032762-0-504819810@DID_PROVIDER]
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Absolute Condition [park]
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action log(NOTICE log|${uuid}|ecallmgr@KZ.DOMAIN.com won call control)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action export(ecallmgr_Ecallmgr-Node=ecallmgr@KZ.DOMAIN.com)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(transfer_ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action ring_ready()
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Caller-Privacy-Number=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Caller-Privacy-Name=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ignore_display_updates=true)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Inception=+15555556900@KAZOO_IP)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_CNAM-From-Cache=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(effective_caller_id_name=CALLER)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Channel-Authorized=true)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Global-Resource=false)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Reseller-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Account-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action set(ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49)
1508032762-0-504819810@DID_PROVIDER Dialplan: sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Action park()
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:216 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_ROUTING -> CS_EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State ROUTING going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA EXECUTE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_state_machine.c:258 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard EXECUTE
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP log(NOTICE log|1508032762-0-504819810@DID_PROVIDER|ecallmgr@KZ.DOMAIN.com won call control)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [NOTICE] mod_dptools.c:1692 log|1508032762-0-504819810@DID_PROVIDER|ecallmgr@KZ.DOMAIN.com won call control
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP export(ecallmgr_Ecallmgr-Node=ecallmgr@KZ.DOMAIN.com)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr@KZ.DOMAIN.com]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ringback]=[%(2000,4000,440,480)]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(transfer_ringback=%(2000,4000,440,480))
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [transfer_ringback]=[%(2000,4000,440,480)]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP ring_ready()
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [NOTICE] mod_sofia.c:2105 Ring-Ready sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP!
1508032762-0-504819810@DID_PROVIDER send 1032 bytes to udp/[KAZOO_IP]:5060 at 13:13:58.151678:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_session.c:913 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER SIP/2.0 180 Ringing
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.01508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [NOTICE] mod_dptools.c:1016 Ring Ready sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP!
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER Contact: <sip:+15555556900@FREESWITCH_IP:11000;transport=udp>
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Accept: application/sdp
1508032762-0-504819810@DID_PROVIDER Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1508032762-0-504819810@DID_PROVIDER Supported: path, replaces
1508032762-0-504819810@DID_PROVIDER Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER P-Asserted-Identity: "+15555556900" <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [early][180]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Fetch-ID]=[da097270-b6fe-11e6-add7-b1e6e2c88a05]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Caller-Privacy-Number=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Caller-Privacy-Number]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Caller-Privacy-Name=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Caller-Privacy-Name]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ignore_display_updates=true)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ignore_display_updates]=[true]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Inception=+15555556900@KAZOO_IP)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Inception]=[+15555556900@KAZOO_IP]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_CNAM-From-Cache=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_CNAM-From-Cache]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(effective_caller_id_name=CALLER)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [effective_caller_id_name]=[CALLER]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Channel-Authorized=true)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Channel-Authorized]=[true]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Global-Resource=false)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Global-Resource]=[false]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Reseller-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Reseller-Billing]=[flat_rate]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Reseller-ID]=[03496e31004899b670a0d23fa72db096]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Account-Billing=flat_rate)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Account-Billing]=[flat_rate]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP set(ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.019561 [DEBUG] mod_dptools.c:1477 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SET [ecallmgr_Account-ID]=[d19d11f7ce18c797263fe4c4a0cdba49]
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP park()
2016-11-30 13:14:36.039533 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Rate-NoCharge-Time=0;ecallmgr_Pvt-Cost=0;ecallmgr_Base-Cost=0;ecallmgr_Rate-Name=Inbound US-1;ecallmgr_Surcharge=0;ecallmgr_Rate-Minimum=6;ecallmgr_Rate-Increment=6;ecallmgr_Rate=240)
2016-11-30 13:14:36.039533 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49;ecallmgr_Account-Billing=flat_rate;ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096;ecallmgr_Reseller-Billing=flat_rate;ecallmgr_Channel-Authorized=true;effective_caller_id_name=CALLER;ecallmgr_Inception=+15555556900@KAZOO_IP;ignore_display_updates=true;ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05;ecallmgr_Application-Node=whistle_apps@KZ.DOMAIN.com;ecallmgr_Application-Name=callflow)
2016-11-30 13:14:36.059549 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(1508032762-0-504819810@DID_PROVIDER ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05;ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49;ignore_display_updates=true;ecallmgr_Inception=+15555556900@KAZOO_IP;effective_caller_id_name=CALLER;ecallmgr_Account-Billing=flat_rate;ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096;ecallmgr_Reseller-Billing=flat_rate;ecallmgr_Channel-Authorized=true;ecallmgr_Application-Node=whistle_apps@KZ.DOMAIN.com;ecallmgr_Application-Name=callflow;effective_caller_id_number=+15554446313)
2016-11-30 13:14:36.259564 [NOTICE] kazoo_node.c:285 log|1508032762-0-504819810@DID_PROVIDER|executing answer
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_session.c:1197 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_ivr.c:616 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Command Execute answer()
1508032762-0-504819810@DID_PROVIDER EXECUTE sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP answer()
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:115:32000:20:48000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G7221:107:16000:20:32000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:115:32000:20:48000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:107:16000:20:32000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[SPEEX:99:8000:20:24600:1]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3595 Set telephone-event payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:2506 Set Codec sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP PCMU/8000 20 ms 160 samples 64000 bits 1 channels
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Original read codec set to PCMU:0
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:3942 Set 2833 dtmf send/recv payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_core_media.c:5178 AUDIO RTP [sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP] FREESWITCH_IP port 19684 -> 4.55.9.194 port 13400 codec: 0 ms: 20
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.259564 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 160 bytes per 20ms
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_media.c:5476 Set 2833 dtmf send payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_media.c:5482 Set 2833 dtmf receive payload to 101
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_media.c:5504 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Set rtp dtmf delay to 40
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP!
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_channel.c:3419 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change RINGING -> EARLY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] mod_sofia.c:782 Local SDP sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP:
1508032762-0-504819810@DID_PROVIDER v=0
1508032762-0-504819810@DID_PROVIDER o=FreeSWITCH 1480491992 1480491993 IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER s=FreeSWITCH
1508032762-0-504819810@DID_PROVIDER c=IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER t=0 0
1508032762-0-504819810@DID_PROVIDER m=audio 19684 RTP/AVP 0 101
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-16
1508032762-0-504819810@DID_PROVIDER a=ptime:20
1508032762-0-504819810@DID_PROVIDER a=sendrecv
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_session.c:913 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [NOTICE] mod_dptools.c:1300 Channel [sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP] has been answered
1508032762-0-504819810@DID_PROVIDER send 1289 bytes to udp/[KAZOO_IP]:5060 at 13:13:58.402977:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER SIP/2.0 200 OK
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.ba1bb297965c145e4c4ba65c882e7433.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:KAZOO_IP;lr=on;ftag=sansay473991408rdb9887>
1508032762-0-504819810@DID_PROVIDER Record-Route: <sip:sansay473991408rdb9887@DID_PROVIDER_SIP_IP:5060;lr;transport=udp>
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 INVITE
1508032762-0-504819810@DID_PROVIDER Contact: <sip:+15555556900@FREESWITCH_IP:11000;transport=udp>
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1508032762-0-504819810@DID_PROVIDER Supported: path, replaces
1508032762-0-504819810@DID_PROVIDER Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1508032762-0-504819810@DID_PROVIDER Content-Type: application/sdp
1508032762-0-504819810@DID_PROVIDER Content-Disposition: session
1508032762-0-504819810@DID_PROVIDER Content-Length: 224
1508032762-0-504819810@DID_PROVIDER P-Asserted-Identity: "+15555556900" <sip:+15555556900@KAZOO_IP>
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER v=0
1508032762-0-504819810@DID_PROVIDER o=FreeSWITCH 1480491992 1480491993 IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER s=FreeSWITCH
1508032762-0-504819810@DID_PROVIDER c=IN IP4 FREESWITCH_IP
1508032762-0-504819810@DID_PROVIDER t=0 0
1508032762-0-504819810@DID_PROVIDER m=audio 19684 RTP/AVP 0 101
1508032762-0-504819810@DID_PROVIDER a=rtpmap:0 PCMU/8000
1508032762-0-504819810@DID_PROVIDER a=rtpmap:101 telephone-event/8000
1508032762-0-504819810@DID_PROVIDER a=fmtp:101 0-16
1508032762-0-504819810@DID_PROVIDER a=ptime:20
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_channel.c:3711 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change EARLY -> ACTIVE
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [completed][200]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.279532 [DEBUG] switch_ivr.c:963 Codec Activated L16@8000hz 1 channels 20ms
1508032762-0-504819810@DID_PROVIDER recv 499 bytes from udp/[KAZOO_IP]:5060 at 13:13:58.445280:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER ACK sip:+15555556900@FREESWITCH_IP:11000;transport=udp SIP/2.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKec4a.e441f2e2c64d926816fb591d4b2b0a6a.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK1sansay473991408rdb9887-200
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 1 ACK
1508032762-0-504819810@DID_PROVIDER Max-Forwards: 50
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER X-AUTH-IP: DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER X-AUTH-PORT: 5060
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.319546 [DEBUG] sofia.c:6658 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP entering state [ready][200]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:36.360070 [DEBUG] switch_rtp.c:5894 Correct ip/port confirmed.
1508032762-0-504819810@DID_PROVIDER recv 495 bytes from udp/[KAZOO_IP]:5060 at 13:14:10.462248:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER BYE sip:+15555556900@FREESWITCH_IP:11000;transport=udp SIP/2.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKbc4a.06cf506f369ee389507e72c44ca37e87.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK2sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 2 BYE
1508032762-0-504819810@DID_PROVIDER Max-Forwards: 50
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER X-AUTH-IP: DID_PROVIDER_SIP_IP
1508032762-0-504819810@DID_PROVIDER X-AUTH-PORT: 5060
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.339580 [DEBUG] switch_core_session.c:1062 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.339580 [NOTICE] sofia.c:952 Hangup sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [CS_EXECUTE] [NORMAL_CLEARING]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_channel.c:3242 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [KILL]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER send 543 bytes to udp/[KAZOO_IP]:5060 at 13:14:10.481654:
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER SIP/2.0 200 OK
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP KAZOO_IP;branch=z9hG4bKbc4a.06cf506f369ee389507e72c44ca37e87.0
1508032762-0-504819810@DID_PROVIDER Via: SIP/2.0/UDP DID_PROVIDER_SIP_IP:5060;branch=z9hG4bK2sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER From: <sip:15554446313@DID_PROVIDER_SIP_IP>;tag=sansay473991408rdb9887
1508032762-0-504819810@DID_PROVIDER To: <sip:+15555556900@KAZOO_IP>;tag=9N3DDN25paK9r
1508032762-0-504819810@DID_PROVIDER Call-ID: 1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER CSeq: 2 BYE
1508032762-0-504819810@DID_PROVIDER User-Agent: 2600hz
1508032762-0-504819810@DID_PROVIDER Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1508032762-0-504819810@DID_PROVIDER Supported: path, replaces
1508032762-0-504819810@DID_PROVIDER Content-Length: 0
1508032762-0-504819810@DID_PROVIDER
1508032762-0-504819810@DID_PROVIDER ------------------------------------------------------------------------
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:2767 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State EXECUTE going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_HANGUP
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:735 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Callstate Change ACTIVE -> HANGUP
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State HANGUP
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP hanging up, cause: NORMAL_CLEARING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard HANGUP, cause: NORMAL_CLEARING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State HANGUP going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_HANGUP -> CS_REPORTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_REPORTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State REPORTING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard REPORTING, cause: NORMAL_CLEARING
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State REPORTING going to sleep
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:498 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State Change CS_REPORTING -> CS_DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1397 Send signal sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [BREAK]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_session.c:1624 Session 4933 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Locked, Waiting on external entities
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [NOTICE] switch_core_session.c:1642 Session 4933 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Ended
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [NOTICE] switch_core_session.c:1646 Close Channel sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP [CS_DESTROY]
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:626 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) Running State Change CS_DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP SOFIA DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:111 sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP Standard DESTROY
1508032762-0-504819810@DID_PROVIDER 2016-11-30 13:14:48.359571 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/15554446313@DID_PROVIDER_SIP_IP) State DESTROY going to sleep
Raw
kazoo.log
Nov 30 13:13:57 KZ 2600hz[22634]: |freeswitch@KZ10.DOMAIN.com|ecallmgr_fs_route:159 (<0.1203.0>) processing dialplan fetch request da097270-b6fe-11e6-add7-b1e6e2c88a05 (call 1508032762-0-504819810@DID_PROVIDER) from freeswitch@KZ10.DOMAIN.com
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:145 (<0.14605.107>) channel authorization request started
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.505.0>) published to callmgr(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key authz.authorize) via <0.1051.0>
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:532 (<0.505.0>) published request with msg id 575881d05e757350 for <0.14605.107>
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.496.0>) published to callmgr(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key route.req.64%2E136%2E173%2E31.15554446313) via <0.1014.0>
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:532 (<0.496.0>) published request with msg id da097270-b6fe-11e6-add7-b1e6e2c88a05 for <0.14604.107>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_util:233 (<0.16571.643>) number '+15555556900' is classified as did_us
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_authz_req:40 (<0.16571.643>) auth for IP DID_PROVIDER_SIP_IP not found, trying number
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_util:262 (<0.16571.643>) number '+15555556900' can be reconciled, proceeding
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|konami_listener:116 (<0.16574.643>) no account id for undefined(undefined) owned by undefined
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|reg_authn_req:280 (<0.16577.643>) looking up IP: DID_PROVIDER_SIP_IP in db sip_auth
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|reg_route_req:49 (<0.16577.643>) failed to find account information from IP DID_PROVIDER_SIP_IP, not replaying route req
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|reorder_route_req:21 (<0.16578.643>) received route request with no account-id
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|whapps_config:273 (<0.16578.643>) setting default for reorder [<<"assume_inbound_e164">>]: undefined
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|reorder_route_req:46 (<0.16578.643>) converted number to e164: +15555556900
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_util:262 (<0.16578.643>) number '+15555556900' can be reconciled, proceeding
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_util:262 (<0.16576.643>) number '+15555556900' can be reconciled, proceeding
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_route_req:25 (<0.16582.643>) received request da097270-b6fe-11e6-add7-b1e6e2c88a05 asking if trunkstore can route this call
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_route_req:39 (<0.16582.643>) insufficient information available to lookup routing for da097270-b6fe-11e6-add7-b1e6e2c88a05, ignoring
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_req:51 (<0.16583.643>) callflow not handling fetch-id da097270-b6fe-11e6-add7-b1e6e2c88a05
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|milliwatt_route_req:41 (<0.16581.643>) milliwatt does not know what to do with this!
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_number:1247 (<0.16571.643>) loaded phone_numbers from d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_number:219 (<0.16571.643>) +15555556900 used_by field (callflow) is correct
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_number_manager:213 (<0.16571.643>) number <<"+15555556900">> is assigned to <<"d19d11f7ce18c797263fe4c4a0cdba49">> in state in_service
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_number:1247 (<0.16578.643>) loaded phone_numbers from d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_number:219 (<0.16578.643>) +15555556900 used_by field (callflow) is correct
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_number_manager:213 (<0.16578.643>) number <<"+15555556900">> is assigned to <<"d19d11f7ce18c797263fe4c4a0cdba49">> in state in_service
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_number:1247 (<0.16576.643>) loaded phone_numbers from d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_number:219 (<0.16576.643>) +15555556900 used_by field (callflow) is correct
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_number_manager:213 (<0.16576.643>) number <<"+15555556900">> is assigned to <<"d19d11f7ce18c797263fe4c4a0cdba49">> in state in_service
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|reorder_route_req:58 (<0.16578.643>) sending known number response: 686 PEBCAK
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16578.643>) published to targeted(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.496.0>-acde4fcf) via <0.1131.0>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_authz_req:106 (<0.16571.643>) authz_local_resources enabled, applying limits for local numbers
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_util:104 (<0.16576.643>) +15555556900 is associated with account d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_inbound:42 (<0.16576.643>) running routines for number +15555556900, fetch-id : da097270-b6fe-11e6-add7-b1e6e2c88a05
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_resources:252 (<0.16576.643>) failed to find matching resource for DID_PROVIDER_SIP_IP:5060(DID_PROVIDER_SIP_IP)
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_resources:668 (<0.16576.643>) local resource cache miss, fetching from db account%2Fd1%2F9d%2F11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_resources:252 (<0.16576.643>) failed to find matching resource for DID_PROVIDER_SIP_IP:5060(DID_PROVIDER_SIP_IP)
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_allotments:156 (<0.16571.643>) checking if account d19d11f7ce18c797263fe4c4a0cdba49 has any allotments for inbound_did_us
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_allotments:156 (<0.16571.643>) checking if account d19d11f7ce18c797263fe4c4a0cdba49 has any allotments for did_us
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_allotments:28 (<0.16571.643>) account has no allotment
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:36 (<0.16571.643>) checking if account d19d11f7ce18c797263fe4c4a0cdba49 has available flat rate trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:162 (<0.16571.643>) account has no inbound trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:162 (<0.16571.643>) account has no outbound trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:175 (<0.16571.643>) account is consuming 0/1 twoway trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_request:209 (<0.16571.643>) account d19d11f7ce18c797263fe4c4a0cdba49 authorized channel: flat_rate
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_allotments:156 (<0.16571.643>) checking if account 03496e31004899b670a0d23fa72db096 has any allotments for inbound_did_us
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_allotments:156 (<0.16571.643>) checking if account 03496e31004899b670a0d23fa72db096 has any allotments for did_us
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_allotments:28 (<0.16571.643>) account has no allotment
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:36 (<0.16571.643>) checking if account 03496e31004899b670a0d23fa72db096 has available flat rate trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:162 (<0.16571.643>) account has no inbound trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:162 (<0.16571.643>) account has no outbound trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_flat_rate:159 (<0.16571.643>) account has unlimited twoway trunks
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|j5_request:200 (<0.16571.643>) reseller 03496e31004899b670a0d23fa72db096 authorized channel: flat_rate
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:698 (<0.505.0>) response for msg id 575881d05e757350 took 49505 micro to return
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_command:219 (<0.14605.107>) freeswitch@KZ10.DOMAIN.com api uuid_setvar_multi 1508032762-0-504819810@DID_PROVIDER ecallmgr_Account-Trunk-Usage=0/0/1/0;ecallmgr_Reseller-Trunk-Usage=0/0/-1/0
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16571.643>) published to targeted(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.505.0>-79a0c85f) via <0.2161.0>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16571.643>) published to callmgr(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key authz.authorize.broadcast) via <0.2161.0>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_cnam:301 (<0.16576.643>) cnam lookup for +15554446313 returned {"HTTP/1.1",200,"OK"}: CALLER
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_inbound:283 (<0.16576.643>) not blacklisted undefined
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16576.643>) published to callmgr(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key route.req.64%2E136%2E173%2E31.15554446313) via <0.1115.0>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_inbound:244 (<0.16576.643>) relaying route request da097270-b6fe-11e6-add7-b1e6e2c88a05
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_req:38 (<0.16600.643>) received request da097270-b6fe-11e6-add7-b1e6e2c88a05 asking if callflows can route this call
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_util:636 (<0.16600.643>) searching for callflow in account%2Fd1%2F9d%2F11f7ce18c797263fe4c4a0cdba49 to satisfy '+15555556900'
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|stepswitch_inbound:25 (<0.16601.643>) fetch-id da097270-b6fe-11e6-add7-b1e6e2c88a05 already has account-id d19d11f7ce18c797263fe4c4a0cdba49, skipping.
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_route_req:25 (<0.16602.643>) received request da097270-b6fe-11e6-add7-b1e6e2c88a05 asking if trunkstore can route this call
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_route_req:32 (<0.16602.643>) call with fetch-id da097270-b6fe-11e6-add7-b1e6e2c88a05 began from outside the network
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:288 (<0.16610.643>) declared queue whistle_apps@KZ.DOMAIN.com-<0.16610.643>-50785b92 via channel <0.14098.624>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.16610.643>) bound whistle_apps@KZ.DOMAIN.com-<0.16610.643>-50785b92 to targeted exchange (routing key whistle_apps@KZ.DOMAIN.com-<0.16610.643>-50785b92) via channel <0.14098.624>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|milliwatt_route_req:41 (<0.16604.643>) milliwatt does not know what to do with this!
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_req:67 (<0.16600.643>) ignore preflow, not set
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_req:95 (<0.16600.643>) callflow b3bedec5862071c3da701483db002113 in d19d11f7ce18c797263fe4c4a0cdba49 satisfies request
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:314 (<0.16610.643>) created consumer amq.ctag-9PthRRfMDXne_mcAtXdLmA via channel <0.14098.624>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_callflow:73 (<0.16610.643>) started AMQP with queue whistle_apps@KZ.DOMAIN.com-<0.16610.643>-50785b92
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_from_offnet:196 (<0.16610.643>) building endpoint for account id d19d11f7ce18c797263fe4c4a0cdba49 with force out true
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|kz_buckets:157 (<0.16600.643>) bucket (callflow d19d11f7ce18c797263fe4c4a0cdba49:b3bedec5862071c3da701483db002113) missing, starting
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_req:206 (<0.16600.643>) callflows knows how to route the call! sending park response
Nov 30 13:13:57 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_cache:353 (<0.14604.107>) waiting for message with ref #Ref<0.0.50.6082>
Nov 30 13:13:57 KZ 2600hz[22460]: |da097270-b6fe-11e6-add7-b1e6e2c88a05|wh_amqp_worker:532 (<0.574.0>) published request with msg id 1508032762-0-504819810@DID_PROVIDER for <0.16600.643>
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_util:113 (<0.16610.643>) cache miss for +15555556900, no results
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_from_offnet:231 (<0.16610.643>) DID +15555556900 not found in d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:57 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|ts_from_offnet:39 (<0.16610.643>) call was not for a trunkstore number
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:196 (<0.14605.107>) call authorized by account d19d11f7ce18c797263fe4c4a0cdba49 as flat_rate
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:215 (<0.14605.107>) call authorized by reseller 03496e31004899b670a0d23fa72db096 as flat_rate
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:227 (<0.14605.107>) rating call in <0.14609.107>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:232 (<0.14605.107>) channel authorization succeeded, allowing call
Nov 30 13:13:58 KZ 2600hz[22634]: |7e56625232315984|wh_cache:938 (<0.1137.0>) storing {authz_response,<<"1508032762-0-504819810@DID_PROVIDER">>} for 3600s
Nov 30 13:13:58 KZ 2600hz[22634]: |7e56625232315984|wh_cache:940 (<0.1137.0>) inserted {authz_response,<<"1508032762-0-504819810@DID_PROVIDER">>}
Nov 30 13:13:58 KZ 2600hz[22634]: |7e56625232315984|wh_cache:942 (<0.1137.0>) inserted origin pointers for {authz_response,<<"1508032762-0-504819810@DID_PROVIDER">>}
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:28 (<0.14605.107>) channel is authorized
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_route:331 (<0.14604.107>) received affirmative route response for request da097270-b6fe-11e6-add7-b1e6e2c88a05
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.496.0>) published to callmgr(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key rate.req) via <0.1014.0>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:532 (<0.496.0>) published request with msg id 531d8f43dd4b4b72 for <0.14609.107>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|hon_rater:21 (<0.16622.643>) valid rating request
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|hon_util:40 (<0.16622.643>) searching for prefixes for +15555556900: [15555556900,1555555690,155555569,15555556,1555555,125248,12524,1252,125,12,1]
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_route:333 (<0.14604.107>) sending XML to freeswitch@KZ10.DOMAIN.com: <document type="freeswitch/xml"><section name="dialplan" description="Route Park Response"><context name="context_2"><extension name="park"><condition><action application="log" data="NOTICE log|${uuid}|ecallmgr@KZ.DOMAIN.com won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecallmgr@KZ.DOMAIN.com"/><condition field="variable_ecallmgr_Bridge-ID" expression="^$"><action application="export" data="ecallmgr_Bridge-ID=${UUID}" inline="true"/></condition><action application="set" data="ringback=%(2000,4000,440,480)"/><action application="set" data="transfer_ringback=%(2000,4000,440,480)"/><action application="ring_ready"/><action application="set" data="ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05"/><action application="set" data="ecallmgr_Caller-Privacy-Number=false"/><action application="set" data="ecallmgr_Caller-Privacy-Name=false"/><action application="set" data="ignore_display_updates=true"/><action application="set" data="ecallmgr_Inception=+15555556900@KAZOO_IP"/><action application="set" data="ecallmgr_CNAM-From-Cache=false"/><action application="set" data="effective_caller_id_name=CALLER"/><action application="set" data="ecallmgr_Channel-Authorized=true"/><action application="set" data="ecallmgr_Global-Resource=false"/><action application="set" data="ecallmgr_Reseller-Billing=flat_rate"/><action application="set" data="ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096"/><action application="set" data="ecallmgr_Account-Billing=flat_rate"/><action application="set" data="ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49"/><action application="park"/></condition></extension></context></section></document>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|hon_rater:75 (<0.16622.643>) candidate rates found, filtering
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|hon_rater:89 (<0.16622.643>) using rate Inbound US-1 for +15554446313 to +15555556900
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|hon_rater:124 (<0.16622.643>) base cost for a minute call: 0
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wnm_util:233 (<0.16622.643>) number '+15555556900' is classified as did_us
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|hon_rater:113 (<0.16622.643>) did_us number discount percentage: {[{<<"_id">>,<<"limits">>},{<<"_rev">>,<<"2-1390bbd179f5e10356d3f9e9e8fb3d85">>},{<<"allow_prepay">>,true},{<<"id">>,<<"limits">>},{<<"inbound_trunks">>,0},{<<"outbound_trunks">>,0},{<<"twoway_trunks">>,1},{<<"ui_metadata">>,{[{<<"version">>,<<"3.22-10">>},{<<"ui">>,<<"monster-ui">>},{<<"origin">>,<<"accounts">>}]}},{<<"pvt_allow_postpay">>,true},{<<"pvt_allow_prepay">>,false},{<<"pvt_max_postpay_amount">>,-20},{<<"pvt_type">>,<<"limits">>},{<<"pvt_vsn">>,<<"1">>},{<<"pvt_account_id">>,<<"d19d11f7ce18c797263fe4c4a0cdba49">>},{<<"pvt_account_db">>,<<"account%2Fd1%2F9d%2F11f7ce18c797263fe4c4a0cdba49">>},{<<"pvt_created">>,63623626643},{<<"pvt_modified">>,63623626643},{<<"pvt_request_id">>,<<"af86ec5b62f2d7f66ae6719616f0f350">>},{<<"pvt_auth_user_id">>,<<"a10d3fd01a7a6313fa047fe56b95013b">>},{<<"pvt_auth_account_id">>,<<"03496e31004899b670a0d23fa72db096">>},{<<"pvt_is_authenticated">>,true}]}
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16622.643>) published to targeted(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.496.0>-acde4fcf) via <0.2139.0>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16622.643>) published to callmgr(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key rate.resp.broadcast) via <0.2139.0>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:698 (<0.496.0>) response for msg id 531d8f43dd4b4b72 took 18757 micro to return
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_authz:316 (<0.14609.107>) setting rating information
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_command:219 (<0.14609.107>) freeswitch@KZ10.DOMAIN.com api uuid_setvar_multi 1508032762-0-504819810@DID_PROVIDER ecallmgr_Rate-NoCharge-Time=0;ecallmgr_Pvt-Cost=0;ecallmgr_Base-Cost=0;ecallmgr_Rate-Name=Inbound US-1;ecallmgr_Surcharge=0;ecallmgr_Rate-Minimum=6;ecallmgr_Rate-Increment=6;ecallmgr_Rate=240
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_route:337 (<0.14604.107>) node freeswitch@KZ10.DOMAIN.com accepted dialplan route response for request da097270-b6fe-11e6-add7-b1e6e2c88a05
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_event_sup:39 (<0.14604.107>) starting event handler for freeswitch@KZ10.DOMAIN.com
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_events:191 (<0.14612.107>) started call event publisher
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14612.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.publisher_usurp.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31707.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1129 (<0.14612.107>) channel started, let's connect
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:208 (<0.14614.107>) starting call control listener
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1210 (<0.14614.107>) binding to call 1508032762-0-504819810@DID_PROVIDER events on node freeswitch@KZ10.DOMAIN.com
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1129 (<0.14614.107>) channel started, let's connect
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_route:363 (<0.14604.107>) started event {ok,<0.14612.107>} and control {ok,<0.14614.107>} processes
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_command:219 (<0.14604.107>) freeswitch@KZ10.DOMAIN.com api uuid_setvar_multi 1508032762-0-504819810@DID_PROVIDER ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49;ecallmgr_Account-Billing=flat_rate;ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096;ecallmgr_Reseller-Billing=flat_rate;ecallmgr_Channel-Authorized=true;effective_caller_id_name=CALLER;ecallmgr_Inception=+15555556900@KAZOO_IP;ignore_display_updates=true;ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05;ecallmgr_Application-Node=whistle_apps@KZ.DOMAIN.com;ecallmgr_Application-Name=callflow
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:288 (<0.14612.107>) declared queue ecallmgr@KZ.DOMAIN.com-<0.14612.107>-96ad1c3c via channel <0.31707.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:288 (<0.14614.107>) declared queue ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9 via channel <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:314 (<0.14612.107>) created consumer amq.ctag-5Q5ZrTwXWWBP9VpuWBP8vw via channel <0.31707.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:867 (<0.14612.107>) queue started: ecallmgr@KZ.DOMAIN.com-<0.14612.107>-96ad1c3c
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1005 (<0.14612.107>) creating new binding: 'call'
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:314 (<0.14614.107>) created consumer amq.ctag-SEnrr8fV_ZAysIZR_a9KBg via channel <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:867 (<0.14614.107>) queue started: ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1005 (<0.14614.107>) creating new binding: 'call'
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.14612.107>) bound ecallmgr@KZ.DOMAIN.com-<0.14612.107>-96ad1c3c to callevt exchange (routing key call.publisher_usurp.1508032762-0-504819810%4064%2E136%2E173%2E225) via channel <0.31707.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.14614.107>) bound ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9 to callevt exchange (routing key call.usurp_control.1508032762-0-504819810%4064%2E136%2E173%2E225) via channel <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1005 (<0.14614.107>) creating new binding: 'dialplan'
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.14614.107>) bound ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9 to callctl exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via channel <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1005 (<0.14614.107>) creating new binding: 'self'
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.14614.107>) bound ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9 to targeted exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via channel <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:524 (<0.14614.107>) sending route_win to whistle_apps@KZ.DOMAIN.com-<0.574.0>-9476ce38
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to targeted(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key whistle_apps@KZ.DOMAIN.com-<0.574.0>-9476ce38) via <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:532 (<0.14614.107>) sending control usurp for da097270-b6fe-11e6-add7-b1e6e2c88a05
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.usurp_control.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:698 (<0.574.0>) response for msg id 1508032762-0-504819810@DID_PROVIDER took 104028 micro to return
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_req:229 (<0.16600.643>) callflow has received a route win, taking control of the call
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_win:37 (<0.16600.643>) setting initial information about the call
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_win:240 (<0.16600.643>) no source endpoint for this call, setting language to default en-us
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_attributes:75 (<0.16600.643>) retaining original caller id <CALLER> +15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_attributes:195 (<0.16600.643>) determined external caller id is <CALLER> +15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_win:261 (<0.16600.643>) bootstrapping with caller id type external: CALLER +15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16600.643>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.1207.0>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_route_win:314 (<0.16600.643>) call has been setup, beginning to process the call
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:707 (<0.16628.643>) executing callflow b3bedec5862071c3da701483db002113
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:708 (<0.16628.643>) account id d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:709 (<0.16628.643>) request +15555556900@KAZOO_IP
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:710 (<0.16628.643>) to +15555556900@KAZOO_IP
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:711 (<0.16628.643>) from 15554446313@DID_PROVIDER_SIP_IP
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:712 (<0.16628.643>) CID CALLER +15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:715 (<0.16628.643>) inception +15555556900@KAZOO_IP: using attributes for an external call
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:717 (<0.16628.643>) authorizing id undefined
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1129 (<0.16628.643>) channel started, let's connect
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:923 (<0.14614.107>) recv and executing set now!
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1073 (<0.14614.107>) executing call command 'set' 5bd40f6fc26cfd21e1883dae9ce5f6e2
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_fs_command:219 (<0.14614.107>) freeswitch@KZ10.DOMAIN.com api uuid_setvar_multi 1508032762-0-504819810@DID_PROVIDER ecallmgr_Fetch-ID=da097270-b6fe-11e6-add7-b1e6e2c88a05;ecallmgr_Account-ID=d19d11f7ce18c797263fe4c4a0cdba49;ignore_display_updates=true;ecallmgr_Inception=+15555556900@KAZOO_IP;effective_caller_id_name=CALLER;ecallmgr_Account-Billing=flat_rate;ecallmgr_Reseller-ID=03496e31004899b670a0d23fa72db096;ecallmgr_Reseller-Billing=flat_rate;ecallmgr_Channel-Authorized=true;ecallmgr_Application-Node=whistle_apps@KZ.DOMAIN.com;ecallmgr_Application-Name=callflow;effective_caller_id_number=+15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:288 (<0.16628.643>) declared queue whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3 via channel <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:314 (<0.16628.643>) created consumer amq.ctag-siqYJ5QgyEqxvxEtUZfFyg via channel <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:867 (<0.16628.643>) queue started: whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1005 (<0.16628.643>) creating new binding: 'call'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.16628.643>) bound whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3 to callevt exchange (routing key call.*.1508032762-0-504819810%4064%2E136%2E173%2E225) via channel <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:1005 (<0.16628.643>) creating new binding: 'self'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:307 (<0.16628.643>) bound whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3 to targeted exchange (routing key whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3) via channel <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:474 (<0.16628.643>) ready to recv events, launching the callflow
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:637 (<0.16628.643>) moving to action 'cf_temporal_route'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_temporal_route:229 (<0.16635.643>) loading temporal route
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_temporal_route:430 (<0.16635.643>) local time for America/New_York is {{2016,11,30},{8,13,58}}
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_temporal_route:129 (<0.16635.643>) continuing with default callflow
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:374 (<0.16628.643>) continuing to child '_'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:629 (<0.16628.643>) stopped caring about <0.16635.643>(#Ref<0.0.494.152474>)
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:637 (<0.16628.643>) moving to action 'cf_callflow'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:522 (<0.16628.643>) unhandled message: {'EXIT',<0.16635.643>,normal}
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_callflow:30 (<0.16636.643>) branching to new callflow bfe2e4586e21af3fb66baec27eb3d54f
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:415 (<0.16628.643>) callflow has been branched
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:637 (<0.16628.643>) moving to action 'cf_user'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:522 (<0.16628.643>) unhandled message: {'EXIT',<0.16636.643>,normal}
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_endpoint:719 (<0.16638.643>) failed to create endpoint: call_forward_not_appropriate
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_endpoint:767 (<0.16638.643>) building a SIP endpoint
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_attributes:75 (<0.16638.643>) retaining original caller id <CALLER> +15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_attributes:195 (<0.16638.643>) determined internal caller id is <CALLER> +15554446313
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_attributes:340 (<0.16638.643>) callee id <CALLEE> +15555556900
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|whapps_config:273 (<0.16638.643>) setting default for callflow [<<"sip_transport">>]: undefined
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|whapps_config:273 (<0.16638.643>) setting default for callflow [<<"custom_sip_interface">>]: undefined
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_user:33 (<0.16638.643>) attempting 1 user devices with strategy simultaneous
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16638.643>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|whapps_call_command:2395 (<0.16638.643>) waiting for bridge for 30000 ms
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:982 (<0.14614.107>) inserting at the tail of the control queue call command bridge
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1073 (<0.14614.107>) executing call command 'bridge' 4d3686d8f4e61c88cd9895e7de923ebf
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1107 (<0.14614.107>) invalid command bridge: not_found
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:151 (<0.14614.107>) stacktrace:
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: ecallmgr_fs_bridge:call_command/3 at (36)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: ecallmgr_call_command:exec_cmd/5 at (36)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: ecallmgr_call_control:execute_control_request/2 at (1084)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: ecallmgr_call_control:handle_dialplan/2 at (870)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: ecallmgr_call_control:handle_cast/2 at (269)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: gen_listener:handle_module_cast/2 at (979)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: gen_server:handle_msg/5 at (607)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_util:158 (<0.14614.107>) st: proc_lib:init_p_do_apply/3 at (227)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"4d3686d8f4e61c88cd9895e7de923ebf">>},{<<"Error-Message">>,<<"Could not execute dialplan action: bridge">>},{<<"Request">>,{[{<<"Timeout">>,20},{<<"Ignore-Forward">>,<<"false">>},{<<"Dial-Endpoint-Method">>,<<"simultaneous">>},{<<"Endpoints">>,[{[{<<"To-Username">>,<<"USERNAME">>},{<<"To-User">>,<<"USERNAME">>},{<<"To-Realm">>,<<"REALM.DOMAIN.com">>},{<<"To-DID">>,<<"+15555556900">>},{<<"Presence-ID">>,<<"1000@REALM.DOMAIN.com">>},{<<"Outbound-Callee-ID-Number">>,<<"+15555556900">>},{<<"Outbound-Callee-ID-Name">>,<<"CALLEE">>},{<<"Custom-SIP-Headers">>,{[{<<"X-KAZOO-AOR">>,<<"sip:USERNAME@REALM.DOMAIN.com">>}]}},{<<"Custom-Channel-Vars">>,{[{<<"SIP-Invite-Domain">>,<<"KAZOO_IP">>},{<<"Media-Encryption-Enforce-Security">>,false},{<<"Account-ID">>,<<"d19d11f7ce18c797263fe4c4a0cdba49">>},{<<"Owner-ID">>,<<"134b26344fbbe90bef6164bf2e53e4e0">>},{<<"Authorizing-ID">>,<<"76d6d7489e19d1023a3c5881c9718bf7">>}]}},{<<"Codecs">>,[<<"PCMU">>,<<"PCMA">>]},{<<"Callee-ID-Number">>,<<"+15555556900">>},{<<"Callee-ID-Name">>,<<"CALLEE">>},{<<"Invite-Format">>,<<"username">>}]}]},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"bridge">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"4d3686d8f4e61c88cd9895e7de923ebf">>},{<<"Event-Name">>,<<"command">>},{<<"Event-Category">>,<<"call">>},{<<"App-Version">>,<<"0.8.2">>},{<<"App-Name">>,<<"callflow">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'bridge'
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:585 (<0.14614.107>) no call commands remain queued, hibernating
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|whapps_call_command:2412 (<0.16638.643>) channel execution error while waiting for bridge: {"Call-ID":"1508032762-0-504819810@DID_PROVIDER","Request":{"Timeout":20,"Ignore-Forward":"false","Dial-Endpoint-Method":"simultaneous","Endpoints":[{"To-Username":"USERNAME","To-User":"USERNAME","To-Realm":"REALM.DOMAIN.com","To-DID":"+15555556900","Presence-ID":"1000@REALM.DOMAIN.com","Outbound-Callee-ID-Number":"+15555556900","Outbound-Callee-ID-Name":"CALLEE","Custom-SIP-Headers":{"X-KAZOO-AOR":"sip:USERNAME@REALM.DOMAIN.com"},"Custom-Channel-Vars":{"SIP-Invite-Domain":"KAZOO_IP","Media-Encryption-Enforce-Security":false,"Account-ID":"d19d11f7ce18c797263fe4c4a0cdba49","Owner-ID":"134b26344fbbe90bef6164bf2e53e4e0","Authorizing-ID":"76d6d7489e19d1023a3c5881c9718bf7"},"Codecs":["PCMU","PCMA"],"Callee-ID-Number":"+15555556900","Callee-ID-Name":"CALLEE","Invite-Format":"username"}],"Call-ID":"1508032762-0-504819810@DID_PROVIDER","Application-Name":"bridge","Server-ID":"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3","Node":"whistle_apps@KZ.DOMAIN.com","Msg-ID":"4d3686d8f4e61c88cd9895e7de923ebf","Event-Name":"command","Event-Category":"call","App-Version":"0.8.2","App-Name":"callflow"},"Error-Message":"Could not execute dialplan action: bridge","Server-ID":"","Node":"ecallmgr@KZ.DOMAIN.com","Msg-ID":"4d3686d8f4e61c88cd9895e7de923ebf","Event-Name":"dialplan","Event-Category":"error","App-Version":"0.8.0","App-Name":"ecallmgr"}
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_user:45 (<0.16638.643>) error bridging to user: {[{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Request">>,{[{<<"Timeout">>,20},{<<"Ignore-Forward">>,<<"false">>},{<<"Dial-Endpoint-Method">>,<<"simultaneous">>},{<<"Endpoints">>,[{[{<<"To-Username">>,<<"USERNAME">>},{<<"To-User">>,<<"USERNAME">>},{<<"To-Realm">>,<<"REALM.DOMAIN.com">>},{<<"To-DID">>,<<"+15555556900">>},{<<"Presence-ID">>,<<"1000@REALM.DOMAIN.com">>},{<<"Outbound-Callee-ID-Number">>,<<"+15555556900">>},{<<"Outbound-Callee-ID-Name">>,<<"CALLEE">>},{<<"Custom-SIP-Headers">>,{[{<<"X-KAZOO-AOR">>,<<"sip:USERNAME@REALM.DOMAIN.com">>}]}},{<<"Custom-Channel-Vars">>,{[{<<"SIP-Invite-Domain">>,<<"KAZOO_IP">>},{<<"Media-Encryption-Enforce-Security">>,false},{<<"Account-ID">>,<<"d19d11f7ce18c797263fe4c4a0cdba49">>},{<<"Owner-ID">>,<<"134b26344fbbe90bef6164bf2e53e4e0">>},{<<"Authorizing-ID">>,<<"76d6d7489e19d1023a3c5881c9718bf7">>}]}},{<<"Codecs">>,[<<"PCMU">>,<<"PCMA">>]},{<<"Callee-ID-Number">>,<<"+15555556900">>},{<<"Callee-ID-Name">>,<<"CALLEE">>},{<<"Invite-Format">>,<<"username">>}]}]},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"bridge">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"4d3686d8f4e61c88cd9895e7de923ebf">>},{<<"Event-Name">>,<<"command">>},{<<"Event-Category">>,<<"call">>},{<<"App-Version">>,<<"0.8.2">>},{<<"App-Name">>,<<"callflow">>}]}},{<<"Error-Message">>,<<"Could not execute dialplan action: bridge">>},{<<"Server-ID">>,<<>>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"4d3686d8f4e61c88cd9895e7de923ebf">>},{<<"Event-Name">>,<<"dialplan">>},{<<"Event-Category">>,<<"error">>},{<<"App-Version">>,<<"0.8.0">>},{<<"App-Name">>,<<"ecallmgr">>}]}
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:374 (<0.16628.643>) continuing to child '_'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:629 (<0.16628.643>) stopped caring about <0.16638.643>(#Ref<0.0.494.152499>)
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:637 (<0.16628.643>) moving to action 'cf_voicemail'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:522 (<0.16628.643>) unhandled message: {'EXIT',<0.16638.643>,normal}
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:982 (<0.14614.107>) inserting at the tail of the control queue call command answer
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1073 (<0.14614.107>) executing call command 'answer' 3bc01a6c7c689de0f8e41dff36f8ff85
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16649.643>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:181 (<0.16649.643>) answered the call and composing the voicemail
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:2049 (<0.16649.643>) opening ceaa40fd60f41295f29d3b89a6df3dc6
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:1888 (<0.16649.643>) loaded voicemail box ceaa40fd60f41295f29d3b89a6df3dc6
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:1903 (<0.16649.643>) mailbox limited to 100 voicemail messages (has 2 currently)
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:396 (<0.16649.643>) playing mailbox greeting to caller
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:468 (<0.16649.643>) mailbox has a greeting: '043bd8236012823cc99a56af0790a765', corrected to '/d19d11f7ce18c797263fe4c4a0cdba49/043bd8236012823cc99a56af0790a765'
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16649.643>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_media_util:264 (<0.16649.643>) using account override for vm-record_message in account d19d11f7ce18c797263fe4c4a0cdba49
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16649.643>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.16649.643>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.14112.624>
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_util:121 (<0.14614.107>) execute on node freeswitch@KZ10.DOMAIN.com(1508032762-0-504819810@DID_PROVIDER) answer(): ok
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:982 (<0.14614.107>) inserting at the tail of the control queue call command play
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:979 (<0.14614.107>) inserting at the tail of the control queue call command noop(3fb58523a9550228042e6e8bb29a101f)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:982 (<0.14614.107>) inserting at the tail of the control queue call command play
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:979 (<0.14614.107>) inserting at the tail of the control queue call command noop(36f4dc5ed612c9fe853ac79f2c199f2f)
Nov 30 13:13:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:979 (<0.14614.107>) inserting at the tail of the control queue call command noop(4a007f361e9440145f2b2af5bf3a7e14)
Nov 30 13:15:05 KZ 2600hz[22460]: |1508033725-0-504877240@DID_PROVIDER|j5_channels:718 (<0.2276.0>) channel disparity with ecallmgr, removing 1508032762-0-504819810@DID_PROVIDER
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_events:465 (<0.14612.107>) call no longer exists, shutting down immediately
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_events:534 (<0.14612.107>) goodbye and thanks for all the fish: normal
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:95 (<0.14612.107>) release consumer <0.14612.107> channel assignment
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:730 (<0.14612.107>) ecallmgr_call_events terminated cleanly, going down
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:404 (<0.14614.107>) call uuid does not exist, executing post-hangup events and terminating
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:547 (<0.14614.107>) our channel has been destroyed, executing any post-hangup commands
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"3bc01a6c7c689de0f8e41dff36f8ff85">>},{<<"Error-Message">>,<<"Could not execute dialplan action: answer">>},{<<"Request">>,{[{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"answer">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"3bc01a6c7c689de0f8e41dff36f8ff85">>},{<<"Event-Name">>,<<"command">>},{<<"Event-Category">>,<<"call">>},{<<"App-Version">>,<<"0.8.2">>},{<<"App-Name">>,<<"callflow">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1188 (<0.14614.107>) started post hangup keep alive timer for 120000ms
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'answer'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:593 (<0.14614.107>) command 'play' is not valid after hangup, skipping
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"a2860c65ebb69688300dc8e0a060e502">>},{<<"Error-Message">>,<<"Could not execute dialplan action: play">>},{<<"Request">>,{[{<<"App-Name">>,<<"callflow">>},{<<"App-Version">>,<<"0.8.2">>},{<<"Event-Category">>,<<"call">>},{<<"Event-Name">>,<<"command">>},{<<"Msg-ID">>,<<"a2860c65ebb69688300dc8e0a060e502">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Terminators">>,[<<"#">>,<<"*">>,<<"0">>,<<"1">>,<<"2">>,<<"3">>,<<"4">>,<<"5">>,<<"6">>,<<"7">>,<<"8">>,<<"9">>]},{<<"Media-Name">>,<<"/d19d11f7ce18c797263fe4c4a0cdba49/043bd8236012823cc99a56af0790a765">>},{<<"Application-Name">>,<<"play">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1199 (<0.14614.107>) reset post hangup keep alive timer
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'play'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:593 (<0.14614.107>) command 'noop' is not valid after hangup, skipping
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|whapps_call_command:2567 (<0.16649.643>) channel execution error while waiting noop or DTMF: {"Call-ID":"1508032762-0-504819810@DID_PROVIDER","Request":{"App-Name":"callflow","App-Version":"0.8.2","Event-Category":"call","Event-Name":"command","Msg-ID":"3fb58523a9550228042e6e8bb29a101f","Node":"whistle_apps@KZ.DOMAIN.com","Server-ID":"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3","Call-ID":"1508032762-0-504819810@DID_PROVIDER","Application-Name":"noop"},"Error-Message":"Could not execute dialplan action: noop","Server-ID":"","Node":"ecallmgr@KZ.DOMAIN.com","Msg-ID":"3fb58523a9550228042e6e8bb29a101f","Event-Name":"dialplan","Event-Category":"error","App-Version":"0.8.0","App-Name":"ecallmgr"}
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:423 (<0.16649.643>) error while playing voicemail greeting: {[{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Request">>,{[{<<"App-Name">>,<<"callflow">>},{<<"App-Version">>,<<"0.8.2">>},{<<"Event-Category">>,<<"call">>},{<<"Event-Name">>,<<"command">>},{<<"Msg-ID">>,<<"3fb58523a9550228042e6e8bb29a101f">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"noop">>}]}},{<<"Error-Message">>,<<"Could not execute dialplan action: noop">>},{<<"Server-ID">>,<<>>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"3fb58523a9550228042e6e8bb29a101f">>},{<<"Event-Name">>,<<"dialplan">>},{<<"Event-Category">>,<<"error">>},{<<"App-Version">>,<<"0.8.0">>},{<<"App-Name">>,<<"ecallmgr">>}]}
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"3fb58523a9550228042e6e8bb29a101f">>},{<<"Error-Message">>,<<"Could not execute dialplan action: noop">>},{<<"Request">>,{[{<<"App-Name">>,<<"callflow">>},{<<"App-Version">>,<<"0.8.2">>},{<<"Event-Category">>,<<"call">>},{<<"Event-Name">>,<<"command">>},{<<"Msg-ID">>,<<"3fb58523a9550228042e6e8bb29a101f">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"noop">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1199 (<0.14614.107>) reset post hangup keep alive timer
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'noop'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:593 (<0.14614.107>) command 'play' is not valid after hangup, skipping
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"008a48d4ccf4fce4de3570b8d9e1cfb9">>},{<<"Error-Message">>,<<"Could not execute dialplan action: play">>},{<<"Request">>,{[{<<"App-Name">>,<<"callflow">>},{<<"App-Version">>,<<"0.8.2">>},{<<"Event-Category">>,<<"call">>},{<<"Event-Name">>,<<"command">>},{<<"Msg-ID">>,<<"008a48d4ccf4fce4de3570b8d9e1cfb9">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Terminators">>,[<<"#">>,<<"*">>,<<"0">>,<<"1">>,<<"2">>,<<"3">>,<<"4">>,<<"5">>,<<"6">>,<<"7">>,<<"8">>,<<"9">>]},{<<"Media-Name">>,<<"prompt://d19d11f7ce18c797263fe4c4a0cdba49/vm-record_message/en-us">>},{<<"Application-Name">>,<<"play">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1199 (<0.14614.107>) reset post hangup keep alive timer
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'play'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:593 (<0.14614.107>) command 'noop' is not valid after hangup, skipping
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"36f4dc5ed612c9fe853ac79f2c199f2f">>},{<<"Error-Message">>,<<"Could not execute dialplan action: noop">>},{<<"Request">>,{[{<<"App-Name">>,<<"callflow">>},{<<"App-Version">>,<<"0.8.2">>},{<<"Event-Category">>,<<"call">>},{<<"Event-Name">>,<<"command">>},{<<"Msg-ID">>,<<"36f4dc5ed612c9fe853ac79f2c199f2f">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"noop">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1199 (<0.14614.107>) reset post hangup keep alive timer
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'noop'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:593 (<0.14614.107>) command 'noop' is not valid after hangup, skipping
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"4a007f361e9440145f2b2af5bf3a7e14">>},{<<"Error-Message">>,<<"Could not execute dialplan action: noop">>},{<<"Request">>,{[{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"noop">>},{<<"Server-ID">>,<<"whistle_apps@KZ.DOMAIN.com-<0.16628.643>-51c0c4d3">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"4a007f361e9440145f2b2af5bf3a7e14">>},{<<"Event-Name">>,<<"command">>},{<<"Event-Category">>,<<"call">>},{<<"App-Version">>,<<"0.8.2">>},{<<"App-Name">>,<<"callflow">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1199 (<0.14614.107>) reset post hangup keep alive timer
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'noop'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:585 (<0.14614.107>) no call commands remain queued, hibernating
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:982 (<0.14614.107>) inserting at the tail of the control queue call command hangup
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:872 (<0.14614.107>) command 'hangup' is not valid after hangup, ignoring
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1169 (<0.14614.107>) sending execution error: [{<<"Msg-ID">>,<<"63735653685f2caf">>},{<<"Error-Message">>,<<"Could not execute dialplan action: hangup">>},{<<"Request">>,{[{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Application-Name">>,<<"hangup">>},{<<"Node">>,<<"whistle_apps@KZ.DOMAIN.com">>},{<<"Msg-ID">>,<<"63735653685f2caf">>},{<<"Event-Name">>,<<"command">>},{<<"Event-Category">>,<<"call">>},{<<"App-Version">>,<<"0.8.2">>},{<<"App-Name">>,<<"callflow">>}]}},{<<"Call-ID">>,<<"1508032762-0-504819810@DID_PROVIDER">>},{<<"Custom-Channel-Vars">>,undefined},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"error">>},{<<"Event-Name">>,<<"dialplan">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecallmgr@KZ.DOMAIN.com">>}]
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_voicemail:184 (<0.16649.643>) compose voicemail complete
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:374 (<0.16628.643>) continuing to child '_'
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:629 (<0.16628.643>) stopped caring about <0.16649.643>(#Ref<0.0.494.152580>)
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:379 (<0.16628.643>) wildcard child does not exist, we are lost...hanging up
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:511 (<0.16628.643>) cf module cf_voicemail down normally
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.574.0>) published to callctl(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key ecallmgr@KZ.DOMAIN.com-<0.14614.107>-6a8c0ac9) via <0.1086.0>
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_worker:610 (<0.574.0>) published message 63735653685f2caf for <0.16628.643>
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|cf_exe:579 (<0.16628.643>) callflow execution has been stopped: normal
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:95 (<0.16628.643>) release consumer <0.16628.643> channel assignment
Nov 30 13:18:58 KZ 2600hz[22460]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:730 (<0.16628.643>) cf_exe terminated cleanly, going down
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:154 (<0.14614.107>) published to callevt(amqp://NAME:PW@KAZOO_IP:5672) exchange (routing key call.diaplan.1508032762-0-504819810%4064%2E136%2E173%2E225) via <0.31754.104>
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:1199 (<0.14614.107>) reset post hangup keep alive timer
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:577 (<0.14614.107>) received control queue unconditional advance, skipping wait for command completion of 'hangup'
Nov 30 13:18:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:585 (<0.14614.107>) no call commands remain queued, hibernating
Nov 30 13:20:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:395 (<0.14614.107>) no new commands received after channel destruction, our job here is done
Nov 30 13:20:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|ecallmgr_call_control:487 (<0.14614.107>) control queue was up for 420017482 microseconds
Nov 30 13:20:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|wh_amqp_channel:95 (<0.14614.107>) release consumer <0.14614.107> channel assignment
Nov 30 13:20:58 KZ 2600hz[22634]: |1508032762-0-504819810@DID_PROVIDER|gen_listener:730 (<0.14614.107>) ecallmgr_call_control terminated cleanly, going down
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment