[Jul  6 15:11:23] Asterisk GIT-11-895dbe5M built by root @ 8-2-phx on a x86_64 running Linux on 2015-07-06 22:02:06 UTC
[Jul  6 15:11:23] DEBUG[16412] config.c: Parsing /etc/asterisk/logger.conf
[Jul  6 15:11:23] VERBOSE[16412] config.c:   == Parsing '/etc/asterisk/logger.conf': Found
[Jul  6 15:11:23] VERBOSE[16412] logger.c:  Asterisk Queue Logger restarted
[Jul  6 15:11:26] DEBUG[15749] manager.c: Running action 'CoreShowChannels'
[Jul  6 15:11:26] DEBUG[15714] chan_sip.c: Destroying SIP dialog 39b56d03450ba48034756f8b685c593c@64.38.193.148:5060
[Jul  6 15:11:27] DEBUG[15749] manager.c: Running action 'QueueStatus'
[Jul  6 15:11:27] DEBUG[15749] manager.c: Running action 'SIPpeers'
[Jul  6 15:11:28] DEBUG[15736] chan_sip.c: = Looking for  Call ID: frfrhi5qpp2pe2olcu0k (Checking From) --From tag 8jdirobqs5 --To-tag   
[Jul  6 15:11:28] DEBUG[15736] acl.c: For destination '50.67.180.112', our source address is '64.38.193.148'.
[Jul  6 15:11:28] DEBUG[15736] chan_sip.c: Setting SIP_TRANSPORT_WS with address 64.38.193.148:5060
[Jul  6 15:11:28] DEBUG[15736] chan_sip.c: Allocating new SIP dialog for frfrhi5qpp2pe2olcu0k - INVITE (No RTP)
[Jul  6 15:11:28] DEBUG[15736][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jul  6 15:11:28] DEBUG[15736][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: outbound"
[Jul  6 15:11:28] DEBUG[15736][C-00000001] sip/reqresp_parser.c: Found SIP option: -outbound-
[Jul  6 15:11:28] DEBUG[15736][C-00000001] sip/reqresp_parser.c: Matched SIP option: outbound
[Jul  6 15:11:28] DEBUG[15736][C-00000001] netsock2.c: Splitting '8-2-phx.xensub.net' into...
[Jul  6 15:11:28] DEBUG[15736][C-00000001] netsock2.c: ...host '8-2-phx.xensub.net' and port ''.
[Jul  6 15:11:28] DEBUG[15736][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 50.67.180.112:55452
[Jul  6 15:11:29] DEBUG[15736] chan_sip.c: = Looking for  Call ID: frfrhi5qpp2pe2olcu0k (Checking From) --From tag 8jdirobqs5 --To-tag as61fa358b  
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Stopping retransmission on 'frfrhi5qpp2pe2olcu0k' of Response 8644: Match Not Found
[Jul  6 15:11:29] DEBUG[15736] chan_sip.c: = Looking for  Call ID: frfrhi5qpp2pe2olcu0k (Checking From) --From tag 8jdirobqs5 --To-tag   
[Jul  6 15:11:29] DEBUG[15736] netsock2.c: Splitting '8-2-phx.xensub.net' into...
[Jul  6 15:11:29] DEBUG[15736] netsock2.c: ...host '8-2-phx.xensub.net' and port ''.
[Jul  6 15:11:29] DEBUG[15736] netsock2.c: Splitting '8-2-phx.xensub.net' into...
[Jul  6 15:11:29] DEBUG[15736] netsock2.c: ...host '8-2-phx.xensub.net' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '8-2-phx.xensub.net' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '8-2-phx.xensub.net' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15736][C-00000001] res_rtp_asterisk.c: Allocated port 33776 for RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.151' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.151' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: RTP instance '0x7fb0e4001728' is setup and ready to go
[Jul  6 15:11:29] DEBUG[15736][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.151' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.151' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] VERBOSE[15736][C-00000001] netsock2.c:   == Using SIP RTP TOS bits 184
[Jul  6 15:11:29] VERBOSE[15736][C-00000001] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Setting NAT on RTP to On
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing session-level SDP o=- 335978753574238722 2 IN IP4 127.0.0.1... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] VERBOSE[15736][C-00000001] netsock2.c:   == Using UDPTL TOS bits 184
[Jul  6 15:11:29] VERBOSE[15736][C-00000001] netsock2.c:   == Using UDPTL CoS mark 5
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Setting NAT on UDPTL to On
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing session-level SDP a=group:BUNDLE audio... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing session-level SDP a=msid-semantic: WMS phqr29S2oh3ML20LUNSEkCEX1fG7z7b6thd2... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 111 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 103 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 104 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 9 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 8 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 106 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 105 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 13 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Setting payload 126 based on m type on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '50.67.180.112' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '50.67.180.112' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 50.67.180.112... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtcp:53094 IN IP4 50.67.180.112... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '192.168.1.175' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '192.168.1.175' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '0' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '0' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=candidate:911959162 1 udp 2122194687 192.168.1.175 53093 typ host generation 0... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '192.168.1.175' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '192.168.1.175' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '0' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '0' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=candidate:911959162 2 udp 2122194686 192.168.1.175 53094 typ host generation 0... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '50.67.180.112' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '50.67.180.112' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '192.168.1.175' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '192.168.1.175' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=candidate:3071501006 1 udp 1685987071 50.67.180.112 53093 typ srflx raddr 192.168.1.175 rport 53093 generation 0... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '50.67.180.112' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '50.67.180.112' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '192.168.1.175' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '192.168.1.175' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=candidate:3071501006 2 udp 1685987070 50.67.180.112 53094 typ srflx raddr 192.168.1.175 rport 53094 generation 0... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '192.168.1.175' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '192.168.1.175' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting 'active' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host 'active' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=candidate:2027460746 1 tcp 1518214911 192.168.1.175 0 typ host tcptype active generation 0... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '192.168.1.175' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '192.168.1.175' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting 'active' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host 'active' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=candidate:2027460746 2 tcp 1518214910 192.168.1.175 0 typ host tcptype active generation 0... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:c4J/WolI1hX2EUOB... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:AmdvWTYN6NxwkZuMoa6gLTrN... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fingerprint:sha-256 28:1A:3F:C7:C0:D3:47:D0:7D:BC:EA:36:9B:AA:22:A8:43:33:00:6C:69:32:6B:0A:7D:10:13:9D:BB:3E:F5:6F... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=setup:actpass... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Unsetting payload 111 on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 minptime=10; useinbandfec=1... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Unsetting payload 103 on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Unsetting payload 104 on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Unsetting payload 106 on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Unsetting payload 105 on 0x7fb1117b11a0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=maxptime:60... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2578637297 cname:gYXbnxRXMaX0q8ll... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2578637297 msid:phqr29S2oh3ML20LUNSEkCEX1fG7z7b6thd2 6e390ef2-e32e-4063-8a94-cd36a144467f... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2578637297 mslabel:phqr29S2oh3ML20LUNSEkCEX1fG7z7b6thd2... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2578637297 label:6e390ef2-e32e-4063-8a94-cd36a144467f... UNSUPPORTED OR FAILED.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Copying payload 0 from 0x7fb1117b11a0 to 0x7fb0e40018f0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Copying payload 8 from 0x7fb1117b11a0 to 0x7fb0e40018f0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Copying payload 9 from 0x7fb1117b11a0 to 0x7fb0e40018f0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Copying payload 13 from 0x7fb1117b11a0 to 0x7fb0e40018f0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] rtp_engine.c: Copying payload 126 from 0x7fb1117b11a0 to 0x7fb0e40018f0
[Jul  6 15:11:29] DEBUG[15736][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: We're settling with these formats: (ulaw)
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Checking SIP call limits for device uckr8p9j
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Updating call counter for incoming call
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '8-2-phx.xensub.net' into...
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '8-2-phx.xensub.net' and port ''.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: Splitting '8-2-phx.xensub.net' into...
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: No provider found, checking channel drivers for SIP - 672-4108
[Jul  6 15:11:29] DEBUG[15736][C-00000001] netsock2.c: ...host '8-2-phx.xensub.net' and port ''.
[Jul  6 15:11:29] DEBUG[15687] chan_sip.c: Checking device state for peer 672-4108
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: Changing state for SIP/672-4108 - state 2 (In use)
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: device 'SIP/672-4108' state '2'
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/672-4108-00000001
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 193
CallerIDName: Xen Call
AccountCode: 672,4108
Exten: 8006941049
Context: 672_agent
Uniqueid: 8-2-phx-1436220689.1


[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: *** Our native formats are (ulaw) 
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/672-4108-00000001
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 193
CallerIDName: Xen Call
AccountCode: 672,4108
Exten: 8006941049
Context: 672_agent
Uniqueid: 8-2-phx-1436220689.1


[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) 
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) 
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: This channel will not be able to handle video.
[Jul  6 15:11:29] DEBUG[15747] app_queue.c: Device 'SIP/672-4108' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: ExtensionStatus
Privilege: call,all
Exten: 193
Context: 672_local
Hint: SIP/672-4108
Status: 1


[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: ExtensionStatus
Privilege: call,all
Exten: 193
Context: 672_local
Hint: SIP/672-4108
Status: 1


[Jul  6 15:11:29] DEBUG[15736][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jul  6 15:11:29] DEBUG[15689] app_queue.c: Extension '193@672_local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: build_route: Contact hop: <sip:krr7fjrm@192.0.2.90;transport=wss;ob>
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: SIP/672-4108-00000001: New call is still down.... Trying... 
[Jul  6 15:11:29] DEBUG[15736][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto WS socket destined for 50.67.180.112:55452
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: No provider found, checking channel drivers for SIP - 672-4108
[Jul  6 15:11:29] DEBUG[15687] chan_sip.c: Checking device state for peer 672-4108
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/672-4108-00000001
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 193
CallerIDName: Xen Call
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 8-2-phx-1436220689.1


[Jul  6 15:11:29] DEBUG[15687] devicestate.c: Changing state for SIP/672-4108 - state 2 (In use)
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: device 'SIP/672-4108' state '2'
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/672-4108-00000001
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 193
CallerIDName: Xen Call
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 8-2-phx-1436220689.1


[Jul  6 15:11:29] DEBUG[15747] app_queue.c: Device 'SIP/672-4108' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'EXTEN' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CONTEXT' is '672_agent'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:1] NoOp("SIP/672-4108-00000001", "Dial 8006941049 from 672_agent") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'EXTEN' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CHANNEL(peername) result is '672-4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'campaignIds' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:2] NoOp("SIP/672-4108-00000001", "CID_INFO={SHELL(php /var/scripts/VOIP/dpScripts/getCID.php 672 8006941049 672-4108 )}") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'EXTEN' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CHANNEL(peername) result is '672-4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'campaignIds' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SHELL(php /var/scripts/VOIP/dpScripts/getCID.php 672 8006941049 672-4108 ) result is '8446002671,8446002671,allowed'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:3] Set("SIP/672-4108-00000001", "CID_INFO=8446002671,8446002671,allowed") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CID_INFO' is '8446002671,8446002671,allowed'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Macro'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:4] Macro("SIP/672-4108-00000001", "SetCID,8446002671,8446002671,allowed") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-SetCID:1] NoOp("SIP/672-4108-00000001", "Setting outbound caller ID") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Macro'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-SetCID:2] Macro("SIP/672-4108-00000001", "InitXencallChannel") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:1] NoOp("SIP/672-4108-00000001", "Initializing XenCall Channel Variables") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'is_remote_bridge' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:2] NoOp("SIP/672-4108-00000001", "is_remote_bridge=") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CALLERID(all) result is '"Xen Call" <193>'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:3] NoOp("SIP/672-4108-00000001", "CALLERID(all)="Xen Call" <193>") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CHANNEL(peername) result is '672-4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:4] NoOp("SIP/672-4108-00000001", "peername=672-4108") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SIP_HEADER(from) result is '<sip:672-4108@8-2-phx.xensub.net>;tag=8jdirobqs5'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:5] NoOp("SIP/672-4108-00000001", "from=<sip:672-4108@8-2-phx.xensub.net>;tag=8jdirobqs5") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SIP_HEADER(to) result is '<sip:8006941049@8-2-phx.xensub.net>'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:6] NoOp("SIP/672-4108-00000001", "to=<sip:8006941049@8-2-phx.xensub.net>") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CHANNEL(peername) result is '672-4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:7] Set("SIP/672-4108-00000001", "Xen_Peer=672-4108") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: Set
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'is_remote_bridge' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:8] GotoIf("SIP/672-4108-00000001", "1?done_peer") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (macro-InitXencallChannel,s,12)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: GotoIf
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-InitXencallChannel:12] NoOp("SIP/672-4108-00000001", "") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: NoOp
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: Macro
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'Force_CNAM' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'Force_CNAM' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-SetCID:3] ExecIf("SIP/672-4108-00000001", "0?Set(ARG2=)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: ExecIf
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'Force_CNAM' (from 'Force_CNAM}" != ""' len 10)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'Force_CNAM' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'Force_CNAM' (from 'Force_CNAM})' len 10)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'Force_CNAM' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is 'allowed'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-SetCID:4] Set("SIP/672-4108-00000001", "CALLERID(pres)=allowed") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: Set
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG2' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-SetCID:5] Set("SIP/672-4108-00000001", "CALLERID(all)=8446002671 <8446002671>") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_macro.c: Executed application: Set
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/672-4108-00000001
CallerIDNum: 8446002671
CallerIDName: 8446002671
Uniqueid: 8-2-phx-1436220689.1
CID-CallingPres: 3 (Presentation Allowed, Network Number)


[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/672-4108-00000001
CallerIDNum: 8446002671
CallerIDName: 8446002671
Uniqueid: 8-2-phx-1436220689.1
CID-CallingPres: 3 (Presentation Allowed, Network Number)


[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'MacroExit'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@macro-SetCID:6] MacroExit("SIP/672-4108-00000001", "") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:5] Set("SIP/672-4108-00000001", "__use_long_duration=1") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'campaignIds' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'campaignIds' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:6] ExecIf("SIP/672-4108-00000001", "0?UserEvent(SetCampaign,campaignIds:)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CALLERID(num) result is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'EXTEN' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'campaignIds' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'UserEvent'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:7] UserEvent("SIP/672-4108-00000001", "InitializeCall,CallType:Manual,DIDNumber:8446002671,TPNumber:8006941049,campaignIds:,clientId:672") in new stack
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: UserEvent
Privilege: user,all
UserEvent: InitializeCall
Uniqueid: 8-2-phx-1436220689.1
CallType:Manual
DIDNumber:8446002671
TPNumber:8006941049
campaignIds:
clientId:672


[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'EXTEN' is '8006941049'
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: UserEvent
Privilege: user,all
UserEvent: InitializeCall
Uniqueid: 8-2-phx-1436220689.1
CallType:Manual
DIDNumber:8446002671
TPNumber:8006941049
campaignIds:
clientId:672


[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Gosub'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@672_agent:8] Gosub("SIP/672-4108-00000001", "DialOut,s,1(8006941049,672)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Channel SIP/672-4108-00000001 has no datastore, so we're allocating one.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG1' to '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG2' to '672'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Goto'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@DialOut:1] Goto("SIP/672-4108-00000001", "8006941049,1") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (DialOut,8006941049,1)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG2' is '672'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG4' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:1] NoOp("SIP/672-4108-00000001", "DialOut ARG1: 8006941049   ARG2: 672   ARG3:      ARG4: ") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:2] Set("SIP/672-4108-00000001", "__DIALOUT_ARG1=8006941049") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG2' is '672'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:3] Set("SIP/672-4108-00000001", "__DIALOUT_ARG2=672") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:4] Set("SIP/672-4108-00000001", "__DIALOUT_ARG3=") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG4' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:5] Set("SIP/672-4108-00000001", "__DIALOUT_ARG4=") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function DIALPLAN_EXISTS(xdnc,8006941049,1) result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Verbose'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:6] Verbose("SIP/672-4108-00000001", "DIALPLAN_EXISTS(xdnc,8006941049,1) = 0") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] app_verbose.c: DIALPLAN_EXISTS(xdnc,8006941049,1) = 0
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function DIALPLAN_EXISTS(xdnc,8006941049,1) result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:7] GotoIf("SIP/672-4108-00000001", "0?xdnc,8006941049,1") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Not taking any branch
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG2' is '672'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Gosub'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:8] Gosub("SIP/672-4108-00000001", "initialize(8006941049,672,,{ARG4})") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG1' to '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG2' to '672'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG3' to ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG4' to '{ARG4}'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:21] Set("SIP/672-4108-00000001", "__CALLEDNUMBER=8006941049") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG2' is '672'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'Xen_Peer' (from 'Xen_Peer}' len 8)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'Xen_Peer' is '672-4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(Xen_Peer,,2) result is '4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:22] Set("SIP/672-4108-00000001", "CDR(accountcode)=672,4108") in new stack
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: NewAccountCode
Privilege: call,all
Channel: SIP/672-4108-00000001
Uniqueid: 8-2-phx-1436220689.1
AccountCode: 672,4108
OldAccountCode: 672,4108


[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'SetAMAFlags'
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: NewAccountCode
Privilege: call,all
Channel: SIP/672-4108-00000001
Uniqueid: 8-2-phx-1436220689.1
AccountCode: 672,4108
OldAccountCode: 672,4108


[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:23] SetAMAFlags("SIP/672-4108-00000001", "billing") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'UserEvent'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:24] UserEvent("SIP/672-4108-00000001", "XCBillingFlag,Billing:2") in new stack
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: UserEvent
Privilege: user,all
UserEvent: XCBillingFlag
Uniqueid: 8-2-phx-1436220689.1
Billing:2


[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALL_COUNT' is NULL
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: UserEvent
Privilege: user,all
UserEvent: XCBillingFlag
Uniqueid: 8-2-phx-1436220689.1
Billing:2


[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:25] ExecIf("SIP/672-4108-00000001", "1?Set(GLOBAL(CALL_COUNT)=0)") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:   == Setting global variable 'CALL_COUNT' to '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALL_COUNT' is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SET(__callnum=1) result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:26] Set("SIP/672-4108-00000001", "GLOBAL(CALL_COUNT)=1") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:   == Setting global variable 'CALL_COUNT' to '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:27] ExecIf("SIP/672-4108-00000001", "1?Set(__COUNTRYPREFIX=1):Set(__COUNTRYPREFIX=)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:28] Set("SIP/672-4108-00000001", "__E164=+18006941049") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CALLERID(num) result is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:29] Set("SIP/672-4108-00000001", "__PRETRUNK_CALLERID=8446002671") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'PRETRUNK_CALLERID' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:30] GotoIf("SIP/672-4108-00000001", "0?strip_countryplus:dont_strip_countryplus") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (DialOut,8006941049,31)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'PRETRUNK_CALLERID' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:31] GotoIf("SIP/672-4108-00000001", "0?strip_country:dont_strip_country") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (DialOut,8006941049,35)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:35] NoOp("SIP/672-4108-00000001", "") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG3' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Gosub'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:36] Gosub("SIP/672-4108-00000001", "GetRoutes(,8006941049)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG1' to ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG2' to '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG3' to ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG4' to ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALLEDNUMBER' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'rc_1_8006941049' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALLEDNUMBER' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'rc_1_8006941049' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:38] ExecIf("SIP/672-4108-00000001", "0?Return()") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'DIALOUT_ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CDR(accountcode) result is '672,4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'PRETRUNK_CALLERID' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'callnum' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'use_long_duration' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'REQ_AMD' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Verbose'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:39] Verbose("SIP/672-4108-00000001", "php /var/scripts/VOIP/dpScripts/getRoutes.php "routeorder=score" "c=1" "n=8006941049" "account=672,4108" "callerid=8446002671" "divisor=1" "use_long_duration=1" "REQ_AMD="") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] app_verbose.c: php /var/scripts/VOIP/dpScripts/getRoutes.php routeorder=score c=1 n=8006941049 account=672,4108 callerid=8446002671 divisor=1 use_long_duration=1 REQ_AMD=
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALLEDNUMBER' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'DIALOUT_ARG1' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CDR(accountcode) result is '672,4108'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'PRETRUNK_CALLERID' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'callnum' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'use_long_duration' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'REQ_AMD' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SHELL(php /var/scripts/VOIP/dpScripts/getRoutes.php "routeorder=score" "c=1" "n=8006941049" "account=672,4108" "callerid=8446002671" "divisor=1" "use_long_duration=1" "REQ_AMD=") result is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:40] Set("SIP/672-4108-00000001", "rc_1_8006941049=10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALLEDNUMBER' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'rc_1_8006941049' is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Return'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:41] Return("SIP/672-4108-00000001", "10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'GOSUB_RETVAL' is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Return'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:37] Return("SIP/672-4108-00000001", "10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'GOSUB_RETVAL' is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function PASSTHRU(10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861) result is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:9] Set("SIP/672-4108-00000001", "route_arr=10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'route_arr' is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:10] GotoIf("SIP/672-4108-00000001", "0?InvalidDestination") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Not taking any branch
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:11] Set("SIP/672-4108-00000001", "__hop_n=0") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'route_arr' (from 'route_arr}' len 9)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'route_arr' is '10539&0.001000&trunk=VOXOX2&rateId=1731229,10601&0.002900&trunk=NOVA&rateId=3427306,10849&0.005000&trunk=RDial_8&rateId=2288861'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SHIFT(route_arr) result is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function SET(route=10539&0.001000&trunk=VOXOX2&rateId=1731229) result is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:12] GotoIf("SIP/672-4108-00000001", "0?route_loop_end") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Not taking any branch
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'hop_n' is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:13] Set("SIP/672-4108-00000001", "__hop_n=1") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'route' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Gosub'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:14] Gosub("SIP/672-4108-00000001", "DialRoute(10539&0.001000&trunk=VOXOX2&rateId=1731229)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG1' to '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Setting 'ARG2' to ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALLEDNUMBER' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:42] NoOp("SIP/672-4108-00000001", "Trying route for 8006941049:   10539&0.001000&trunk=VOXOX2&rateId=1731229") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(ARG1,&,1) result is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:43] Set("SIP/672-4108-00000001", "__routeId=10539") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_IP' is '207.238.191.252'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:44] ExecIf("SIP/672-4108-00000001", "0?Return(advance)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(ARG1,&,2) result is '0.001000'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:45] Set("SIP/672-4108-00000001", "cost=0.001000") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(ARG1,&,3) result is 'trunk=VOXOX2'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:46] Set("SIP/672-4108-00000001", "__TRUNKNAME=trunk=VOXOX2") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'TRUNKNAME' (from 'TRUNKNAME}' len 9)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'TRUNKNAME' is 'trunk=VOXOX2'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(TRUNKNAME,=,2) result is 'VOXOX2'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:47] Set("SIP/672-4108-00000001", "__TRUNKNAME=VOXOX2") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(ARG1,&,4) result is 'rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:48] Set("SIP/672-4108-00000001", "__rateId=rateId=1731229") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'rateId' (from 'rateId}' len 6)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'rateId' is 'rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(rateId,=,2) result is '1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:49] Set("SIP/672-4108-00000001", "__rateId=1731229") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ARG1' is '10539&0.001000&trunk=VOXOX2&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CUT(ARG1,&,5) result is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:50] Set("SIP/672-4108-00000001", "chargerate=") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'cost' is '0.001000'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_RATE' is '0.011'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:51] ExecIf("SIP/672-4108-00000001", "0?Set(cost=0.011)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'cost' is '0.001000'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'rateId' is '1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:52] Set("SIP/672-4108-00000001", "__userfield_copy=trunk_cost=0.001000,outtrunk=10539,&rateId=1731229") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'chargerate' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'userfield_copy' is 'trunk_cost=0.001000,outtrunk=10539,&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'chargerate' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:53] ExecIf("SIP/672-4108-00000001", "0?Set(__userfield_copy=trunk_cost=0.001000,outtrunk=10539,&rateId=1731229,chargerate=)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'userfield_copy' is 'trunk_cost=0.001000,outtrunk=10539,&rateId=1731229'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:54] Set("SIP/672-4108-00000001", "CDR(userfield)=trunk_cost=0.001000,outtrunk=10539,&rateId=1731229") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'COUNTRYPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:55] GotoIf("SIP/672-4108-00000001", "1?northamerica:overseas") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (DialOut,8006941049,58)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_CIDPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'PRETRUNK_CALLERID' is '8446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:58] Set("SIP/672-4108-00000001", "CALLERID(num)=18446002671") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_PREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'CALLEDNUMBER' is '8006941049'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'TRUNKNAME' is 'VOXOX2'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:59] Set("SIP/672-4108-00000001", "dialstring=18006941049@VOXOX2") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Goto'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:60] Goto("SIP/672-4108-00000001", "done_route_customize") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (DialOut,8006941049,61)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CALLERID(num) result is '18446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function CALLERID(num) result is '18446002671'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function LEN(18446002671) result is '11'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_CIDPREFIX' is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'dialstring' is '18006941049@VOXOX2'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'NoOp'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:61] NoOp("SIP/672-4108-00000001", "Caller ID 18446002671 len 11  ROUTE10539_CIDPREFIX=1 dialstring=18006941049@VOXOX2") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Progress'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:62] Progress("SIP/672-4108-00000001", "") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Setting framing from config on incoming call
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) 
[Jul  6 15:11:29] DEBUG[16532][C-00000001] sip/sdp_crypto.c: local_key64 29tyA4FIMdBRGZrCqDUrZ+5BCX3CWN5TAzEPSwWj len 40
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: -- Done with adding codecs to SDP
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 183' onto WS socket destined for 50.67.180.112:55452
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_USE_SBC' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:63] Set("SIP/672-4108-00000001", "__using_sbc=") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'using_sbc' is ''
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'GotoIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:64] GotoIf("SIP/672-4108-00000001", "1?nosbc:yessbc") in new stack
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Goto (DialOut,8006941049,70)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'routeId' is '10539'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'ROUTE10539_ONLY_SBC' is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '0'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'ExecIf'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:70] ExecIf("SIP/672-4108-00000001", "0?Return(advance)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'dialstring' is '18006941049@VOXOX2'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'dial_timeout' is '85'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'DIALOUT_OPTIONS' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Expression result is '1'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'DIALOUT_OPTIONS' is NULL
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Function IF(1?TreF(DialOut_MinDur^s^1)U(DialOut_Cheap_AMD)b(DialOut_Cheap_AMD_Init^s^1):) result is 'TreF(DialOut_MinDur^s^1)U(DialOut_Cheap_AMD)b(DialOut_Cheap_AMD_Init^s^1)'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Dial'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [8006941049@DialOut:71] Dial("SIP/672-4108-00000001", "SIP/18006941049@VOXOX2,85,TreF(DialOut_MinDur^s^1)U(DialOut_Cheap_AMD)b(DialOut_Cheap_AMD_Init^s^1)") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Allocating new SIP dialog for 10289d8e77ced45271e656cd1eb8bf8d@64.38.193.148:5060 - INVITE (No RTP)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb0c402c2e8'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_rtp_asterisk.c: Allocated port 27572 for RTP instance '0x7fb0c402c2e8'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: Splitting '64.38.193.151' into...
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: ...host '64.38.193.151' and port ''.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: Splitting '64.38.193.148' into...
[Jul  6 15:11:29] DEBUG[16532][C-00000001] netsock2.c: ...host '64.38.193.148' and port ''.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] rtp_engine.c: RTP instance '0x7fb0c402c2e8' is setup and ready to go
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb0c402c2e8'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] netsock2.c:   == Using SIP RTP TOS bits 184
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Setting NAT on RTP to Off
[Jul  6 15:11:29] DEBUG[16532][C-00000001] acl.c: For destination '207.238.191.252', our source address is '64.38.193.148'.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 64.38.193.148:5060
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Setting NAT on RTP to Off
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: SIP call-id changed from '10289d8e77ced45271e656cd1eb8bf8d@64.38.193.148:5060' to '14351afb69a57bdd7bfb1ca1671adf9f@64.38.193.148:5060'
[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/VOXOX2-00000002
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 
CallerIDName: 
AccountCode: 
Exten: 
Context: incoming
Uniqueid: 8-2-phx-1436220689.2


[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: *** Our native formats are (ulaw) 
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) 
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) 
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/VOXOX2-00000002
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 
CallerIDName: 
AccountCode: 
Exten: 
Context: incoming
Uniqueid: 8-2-phx-1436220689.2


[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: This channel will not be able to handle video.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001]
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable using_sbc from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable userfield_copy from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable rateId from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable TRUNKNAME from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable routeId from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable hop_n from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable PRETRUNK_CALLERID from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable E164 from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable COUNTRYPREFIX from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable callnum from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable CALLEDNUMBER from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable DIALOUT_ARG4 from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable DIALOUT_ARG3 from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable DIALOUT_ARG2 from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable DIALOUT_ARG1 from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Inheriting variable use_long_duration from SIP/672-4108-00000001 to SIP/VOXOX2-00000002.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Gosub args:DialOut_Cheap_AMD_Init,s,1 new_args:DialOut_Cheap_AMD_Init,s,1
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/VOXOX2-00000002
CallerIDNum: 8006941049
CallerIDName: 
Uniqueid: 8-2-phx-1436220689.2
CID-CallingPres: 0 (Presentation Allowed, Not Screened)


[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/VOXOX2-00000002
CallerIDNum: 8006941049
CallerIDName: 
Uniqueid: 8-2-phx-1436220689.2
CID-CallingPres: 0 (Presentation Allowed, Not Screened)


[Jul  6 15:11:29] VERBOSE[16532][C-00000001] app_stack.c:     -- SIP/VOXOX2-00000002 Internal Gosub(DialOut_Cheap_AMD_Init,s,1) start
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: SIP/VOXOX2-00000002 Original location: incoming,8006941049,1
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Channel SIP/VOXOX2-00000002 has no datastore, so we're allocating one.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Gosub exited with status 0
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Result of 'EPOCH' is '1436220689'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Set'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@DialOut_Cheap_AMD_Init:1] Set("SIP/VOXOX2-00000002", "_DIALSTART_EPOCH=1436220689") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] pbx.c: Launching 'Return'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] pbx.c:     -- Executing [s@DialOut_Cheap_AMD_Init:2] Return("SIP/VOXOX2-00000002", "") in new stack
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: Spawn extension (incoming,8006941049,1) exited with -1 on 'SIP/VOXOX2-00000002'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] app_stack.c:   == Spawn extension (incoming, 8006941049, 1) exited non-zero on 'SIP/VOXOX2-00000002'
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] app_stack.c:     -- SIP/VOXOX2-00000002 Internal Gosub(DialOut_Cheap_AMD_Init,s,1) complete GOSUB_RETVAL=
[Jul  6 15:11:29] DEBUG[16532][C-00000001] app_stack.c: SIP/VOXOX2-00000002 Ending location: incoming,8006941049,1
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Outgoing Call for 18006941049
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Updating call counter for outgoing call
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: No provider found, checking channel drivers for SIP - VOXOX2
[Jul  6 15:11:29] DEBUG[15687] chan_sip.c: Checking device state for peer VOXOX2
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: Changing state for SIP/VOXOX2 - state 6 (Ringing)
[Jul  6 15:11:29] DEBUG[15687] devicestate.c: device 'SIP/VOXOX2' state '6'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: ** Our prefcodec: (ulaw) 
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: -- Done with adding codecs to SDP
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw)
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 14351afb69a57bdd7bfb1ca1671adf9f@64.38.193.148:5060
[Jul  6 15:11:29] DEBUG[16532][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 207.238.191.252:5060
[Jul  6 15:11:29] VERBOSE[16532][C-00000001] app_dial.c:     -- Called SIP/18006941049@VOXOX2
[Jul  6 15:11:29] DEBUG[15749] manager.c: Examining event:
Event: Dial
Privilege: call,all
SubEvent: Begin
Channel: SIP/672-4108-00000001
Destination: SIP/VOXOX2-00000002
CallerIDNum: 18446002671
CallerIDName: 8446002671
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
UniqueID: 8-2-phx-1436220689.1
DestUniqueID: 8-2-phx-1436220689.2
Dialstring: 18006941049@VOXOX2


[Jul  6 15:11:29] DEBUG[15752] manager.c: Examining event:
Event: Dial
Privilege: call,all
SubEvent: Begin
Channel: SIP/672-4108-00000001
Destination: SIP/VOXOX2-00000002
CallerIDNum: 18446002671
CallerIDName: 8446002671
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
UniqueID: 8-2-phx-1436220689.1
DestUniqueID: 8-2-phx-1436220689.2
Dialstring: 18006941049@VOXOX2


[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Driver for channel 'SIP/672-4108-00000001' does not support indication 3, emulating it
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Set channel SIP/672-4108-00000001 to write format slin
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  6 15:11:29] DEBUG[16532][C-00000001] channel.c: Prodding channel 'SIP/672-4108-00000001'
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_rtp_asterisk.c: Received frame with no data for RTP instance '0x7fb0e4001728' so dropping frame
[Jul  6 15:11:29] DEBUG[15747] app_queue.c: Device 'SIP/VOXOX2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15714] chan_sip.c: = Looking for  Call ID: 14351afb69a57bdd7bfb1ca1671adf9f@64.38.193.148:5060 (Checking To) --From tag as18d716f9 --To-tag   
[Jul  6 15:11:29] DEBUG[15714][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '14351afb69a57bdd7bfb1ca1671adf9f@64.38.193.148:5060' Request 102: Found
[Jul  6 15:11:29] DEBUG[15714][C-00000001] chan_sip.c: SIP response 100 to standard invite
[Jul  6 15:11:29] DEBUG[15698] netsock2.c: Splitting '50.67.180.112' into...
[Jul  6 15:11:29] DEBUG[15698] netsock2.c: ...host '50.67.180.112' and port ''.
[Jul  6 15:11:29] DEBUG[15698] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb0e4001728'
[Jul  6 15:11:29] DEBUG[15698] netsock2.c: Splitting '50.67.180.112' into...
[Jul  6 15:11:29] DEBUG[15698] netsock2.c: ...host '50.67.180.112' and port ''.
[Jul  6 15:11:29] DEBUG[16532][C-00000001] res_srtp.c: Adding new policy for SSRC 484532056
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:29] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:30] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[15749] manager.c: Running action 'QueueStatus'
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[15749] manager.c: Running action 'SIPpeers'
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=9.61E+04, Et=2.52E+06, s/n=      0.04
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=9.56E+04, Et=9.79E+06, s/n=      0.01
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=6.31E+05, Et=3.76E+07, s/n=      0.02
[Jul  6 15:11:31] DEBUG[16532][C-00000001] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=      -nan
[Jul  6 15:11:31] DEBUG[15714] chan_sip.c: = Looking for  Call ID: 14351afb69a57bdd7bfb1ca1671adf9f@64.38.193.148:5060 (Checking To) --From tag as18d716f9 --To-tag sansay2565414562rdb77635  
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '14351afb69a57bdd7bfb1ca1671adf9f@64.38.193.148:5060' Request 102: Found
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: SIP response 183 to standard invite
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: build_route: Record-Route hop: <sip:sansay2565414562rdb77635@207.238.191.252:5060;lr;transport=udp>
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing session-level SDP o=Sansay-VSXi 188 1 IN IP4 207.238.191.252... OK.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing session-level SDP s=Session Controller... UNSUPPORTED OR FAILED.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] netsock2.c: Splitting '23.29.31.43' into...
[Jul  6 15:11:31] DEBUG[15714][C-00000001] netsock2.c: ...host '23.29.31.43' and port ''.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 23.29.31.43... OK.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0x7fb1119a3e90
[Jul  6 15:11:31] DEBUG[15714][C-00000001] rtp_engine.c: Setting payload 101 based on m type on 0x7fb1119a3e90
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jul  6 15:11:31] DEBUG[15714][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.