[Oct 27 15:50:05] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog '320458e777c264c0188aba1c346877eb@10.11.2.232:5060' [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: Destroying SIP dialog 320458e777c264c0188aba1c346877eb@10.11.2.232:5060 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '320458e777c264c0188aba1c346877eb@10.11.2.232:5060' [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 001. NewChan Channel SIP/termination1.sd-0000028b - from 320458e777c264c0188 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - INVITE [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 trying -- your call is important to [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 180 Ringing [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 200 OK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 006. TxReq ACK / 102 ACK - ACK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 007. ReInv Re-invite sent [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 008. TxReqRel INVITE / 103 INVITE - INVITE [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 009. Rx SIP/2.0 / 103 INVITE / 100 trying -- your call is important to [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 010. Rx SIP/2.0 / 103 INVITE / 200 OK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 011. TxReq ACK / 103 ACK - ACK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 012. ReInv Re-invite sent [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 013. TxReqRel INVITE / 104 INVITE - INVITE [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 014. Rx SIP/2.0 / 104 INVITE / 100 trying -- your call is important to [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 015. Rx SIP/2.0 / 104 INVITE / 200 OK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 016. TxReq ACK / 104 ACK - ACK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 017. ReInv Re-invite sent [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 018. TxReqRel INVITE / 105 INVITE - INVITE [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 019. Rx SIP/2.0 / 105 INVITE / 100 trying -- your call is important to [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 020. Rx SIP/2.0 / 105 INVITE / 200 OK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 021. TxReq ACK / 105 ACK - ACK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 022. ReInv Re-invite sent [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 023. TxReqRel INVITE / 106 INVITE - INVITE [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 024. Rx SIP/2.0 / 106 INVITE / 100 trying -- your call is important to [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 025. Rx SIP/2.0 / 106 INVITE / 200 OK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 026. TxReq ACK / 106 ACK - ACK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 027. Rx BYE / 2 BYE / sip:81@10.11.2.232:5060 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 028. RTCPaudio Quality:ssrc=729659054;themssrc=1922196870;lp=0;rxjitter=0.0000 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 029. RTCPaudioJitter Quality:minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 030. RTCPaudioLoss Quality:minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.00000 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 031. RTCPaudioRTT Quality:minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrt [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 032. SchedDestroy 32000 ms [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 033. TxResp SIP/2.0 / 2 BYE - 200 OK [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 034. Hangup Cause Normal Clearing [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: 035. AutoDestroy 320458e777c264c0188aba1c346877eb@10.11.2.232:5060 [Oct 27 15:50:05] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '320458e777c264c0188aba1c346877eb@10.11.2.232:5060' [Oct 27 15:50:05] DEBUG[1325] rtp_engine.c: Destroyed RTP instance '0x7f644c1f10b8' [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog '099fc2416ac93034383667c33a1b0ebb@10.11.2.225:5060' [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: Destroying SIP dialog 099fc2416ac93034383667c33a1b0ebb@10.11.2.225:5060 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '099fc2416ac93034383667c33a1b0ebb@10.11.2.225:5060' [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 001. Rx INVITE / 102 INVITE / sip:27609336033@10.11.2.232 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 002. NewChan Channel SIP/voicesystem-one-0000028c - from 099fc2416ac93034383 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 003. Xfer INVITE/Replace received [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 004. TxResp SIP/2.0 / 102 INVITE - 100 Trying [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 005. TxRespRel SIP/2.0 / 102 INVITE - 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 006. Masq Old channel: SIP/origination1.sd-0000028a [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 007. Masq (cont) ...new owner: SIP/voicesystem-one-0000028c [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 008. Rx ACK / 102 ACK / sip:27609336033@10.11.2.232:5060 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 009. ReInv Re-invite sent [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 010. TxReqRel INVITE / 102 INVITE - INVITE [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 011. Rx SIP/2.0 / 102 INVITE / 100 Trying [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 012. Rx SIP/2.0 / 102 INVITE / 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 013. TxReq ACK / 102 ACK - ACK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 014. ReInv Re-invite sent [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 015. TxReqRel INVITE / 103 INVITE - INVITE [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 016. Rx SIP/2.0 / 103 INVITE / 100 Trying [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 017. Rx SIP/2.0 / 103 INVITE / 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 018. TxReq ACK / 103 ACK - ACK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 019. ReInv Re-invite sent [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 020. TxReqRel INVITE / 104 INVITE - INVITE [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 021. Rx SIP/2.0 / 104 INVITE / 100 Trying [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 022. Rx SIP/2.0 / 104 INVITE / 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 023. TxReq ACK / 104 ACK - ACK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 024. ReInv Re-invite sent [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 025. TxReqRel INVITE / 105 INVITE - INVITE [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 026. Rx SIP/2.0 / 105 INVITE / 100 Trying [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 027. Rx SIP/2.0 / 105 INVITE / 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 028. TxReq ACK / 105 ACK - ACK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 029. Rx BYE / 103 BYE / sip:27609336033@10.11.2.232:5060 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 030. RTCPaudio Quality:ssrc=832278077;themssrc=593610094;lp=0;rxjitter=0.00012 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 031. RTCPaudioJitter Quality:minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 032. RTCPaudioLoss Quality:minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.00000 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 033. RTCPaudioRTT Quality:minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrt [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 034. SchedDestroy 32000 ms [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 035. TxResp SIP/2.0 / 103 BYE - 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 036. Hangup Cause Normal Clearing [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 037. AutoDestroy 099fc2416ac93034383667c33a1b0ebb@10.11.2.225:5060 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '099fc2416ac93034383667c33a1b0ebb@10.11.2.225:5060' [Oct 27 15:50:06] DEBUG[1325] rtp_engine.c: Destroyed RTP instance '0x7f64482df9d8' [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: Destroying SIP dialog 778c9137-ad2ecb50-c46599c5@10.11.255.6 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '778c9137-ad2ecb50-c46599c5@10.11.255.6' [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 001. Rx INVITE / 2 INVITE / sip:87@10.11.2.232:5060 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 002. NewChan Channel SIP/origination1.sd-0000028a - from 778c9137-ad2ecb50-c [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 003. TxResp SIP/2.0 / 2 INVITE - 100 Trying [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 004. TxRespRel SIP/2.0 / 2 INVITE - 200 OK [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 005. Rx ACK / 2 ACK / sip:87@10.11.2.232:5060 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 006. Masq Old channel: Bridge/SIP/origination1.sd-0000028a [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 007. Masq (cont) ...new owner: SIP/origination1.sd-0000028a [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 008. Masq Old channel: SIP/voicesystem-one-0000028c [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 009. Masq (cont) ...new owner: SIP/origination1.sd-0000028a [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 010. SchedDestroy 32000 ms [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: 011. AutoDestroy 778c9137-ad2ecb50-c46599c5@10.11.255.6 [Oct 27 15:50:06] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '778c9137-ad2ecb50-c46599c5@10.11.255.6' [Oct 27 15:50:08] DEBUG[1325] chan_sip.c: = Looking for Call ID: 3637004963eaa4ea-22068@10.11.2.102 (Checking From) --From tag c9428db5fa22760d6f58389a1f3fceb6-7fb6 --To-tag [Oct 27 15:50:08] DEBUG[1325] acl.c: For destination '10.11.2.102', our source address is '10.11.2.232'. [Oct 27 15:50:08] DEBUG[1325] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:50:08] DEBUG[1325] netsock2.c: Splitting '10.11.2.102' into... [Oct 27 15:50:08] DEBUG[1325] netsock2.c: ...host '10.11.2.102' and port ''. [Oct 27 15:50:08] DEBUG[1325] chan_sip.c: Allocating new SIP dialog for 3637004963eaa4ea-22068@10.11.2.102 - OPTIONS (No RTP) [Oct 27 15:50:08] DEBUG[1325] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Oct 27 15:50:08] DEBUG[1325] netsock2.c: Splitting '10.11.2.232:5060' into... [Oct 27 15:50:08] DEBUG[1325] netsock2.c: ...host '10.11.2.232' and port ''. [Oct 27 15:50:08] DEBUG[1325] netsock2.c: Splitting 'localhost' into... [Oct 27 15:50:08] DEBUG[1325] netsock2.c: ...host 'localhost' and port ''. [Oct 27 15:50:08] DEBUG[1325] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.11.2.102:5060 [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog '3637004963eaa4db-22068@10.11.2.102' [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: Destroying SIP dialog 3637004963eaa4db-22068@10.11.2.102 [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '3637004963eaa4db-22068@10.11.2.102' [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: 001. Rx OPTIONS / 10 OPTIONS / sip:10.11.2.232:5060 [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: 002. TxResp SIP/2.0 / 10 OPTIONS - 200 OK [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: 003. SchedDestroy 32000 ms [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: 004. AutoDestroy 3637004963eaa4db-22068@10.11.2.102 [Oct 27 15:50:10] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '3637004963eaa4db-22068@10.11.2.102' [Oct 27 15:50:17] DEBUG[1325] chan_sip.c: = Looking for Call ID: dbce2dff-c466daf8-620f38cd@10.11.255.6 (Checking From) --From tag E711C95A-94BFEB27 --To-tag [Oct 27 15:50:17] DEBUG[1325] acl.c: For destination '10.11.2.102', our source address is '10.11.2.232'. [Oct 27 15:50:17] DEBUG[1325] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:50:17] DEBUG[1325] netsock2.c: Splitting '10.11.2.102' into... [Oct 27 15:50:17] DEBUG[1325] netsock2.c: ...host '10.11.2.102' and port ''. [Oct 27 15:50:17] DEBUG[1325] chan_sip.c: Allocating new SIP dialog for dbce2dff-c466daf8-620f38cd@10.11.255.6 - INVITE (No RTP) [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 27 15:50:17] DEBUG[1325][C-0000037f] sip/reqresp_parser.c: Begin: parsing SIP "Supported: 100rel,replaces" [Oct 27 15:50:17] DEBUG[1325][C-0000037f] sip/reqresp_parser.c: Found SIP option: -100rel- [Oct 27 15:50:17] DEBUG[1325][C-0000037f] sip/reqresp_parser.c: Matched SIP option: 100rel [Oct 27 15:50:17] DEBUG[1325][C-0000037f] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 27 15:50:17] DEBUG[1325][C-0000037f] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: Splitting '10.11.2.102' into... [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: ...host '10.11.2.102' and port ''. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: Splitting '10.11.2.9' into... [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: ...host '10.11.2.9' and port ''. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f64482524e8' [Oct 27 15:50:17] DEBUG[1325][C-0000037f] res_rtp_asterisk.c: Allocated port 13974 for RTP instance '0x7f64482524e8' [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: RTP instance '0x7f64482524e8' is setup and ready to go [Oct 27 15:50:17] DEBUG[1325][C-0000037f] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f64482524e8' [Oct 27 15:50:17] VERBOSE[1325][C-0000037f] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Setting NAT on RTP to On [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing session-level SDP o=- 1414450216 1414450216 IN IP4 10.11.255.6... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED OR FAILED. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: Splitting '10.11.255.6' into... [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: ...host '10.11.255.6' and port ''. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing session-level SDP c=IN IP4 10.11.255.6... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing session-level SDP a=sendrecv... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Setting payload 9 based on m type on 0x7f64381c9c00 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Setting payload 0 based on m type on 0x7f64381c9c00 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Setting payload 8 based on m type on 0x7f64381c9c00 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Setting payload 18 based on m type on 0x7f64381c9c00 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Setting payload 127 based on m type on 0x7f64381c9c00 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:127 telephone-event/8000... OK. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f64482524e8' [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Copying payload 0 from 0x7f64381c9c00 to 0x7f64482526b0 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Copying payload 8 from 0x7f64381c9c00 to 0x7f64482526b0 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Copying payload 9 from 0x7f64381c9c00 to 0x7f64482526b0 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Copying payload 18 from 0x7f64381c9c00 to 0x7f64482526b0 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] rtp_engine.c: Copying payload 127 from 0x7f64381c9c00 to 0x7f64482526b0 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f64482524e8' [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: We're settling with these formats: (ulaw) [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Checking SIP call limits for device [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Updating call counter for incoming call [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: Splitting '10.11.2.232:5060' into... [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: ...host '10.11.2.232' and port ''. [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: Splitting '10.11.2.9' into... [Oct 27 15:50:17] DEBUG[1325][C-0000037f] netsock2.c: ...host '10.11.2.9' and port ''. [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 2132013013 CallerIDName: Alex AccountCode: Exten: 87 Context: subscriber Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 2132013013 CallerIDName: Alex AccountCode: Exten: 87 Context: subscriber Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: *** Our native formats are (ulaw) [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: *** Joint capabilities are (ulaw) [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: *** Our capabilities are (ulaw) [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: This channel will not be able to handle video. [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPURI Value: sip:2132013013@10.11.255.6:5060 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPURI Value: sip:2132013013@10.11.255.6:5060 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPDOMAIN Value: 10.11.2.232 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPDOMAIN Value: 10.11.2.232 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPCALLID Value: dbce2dff-c466daf8-620f38cd@10.11.255.6 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPCALLID Value: dbce2dff-c466daf8-620f38cd@10.11.255.6 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 Channeltype: SIP SIPcallid: dbce2dff-c466daf8-620f38cd@10.11.255.6 SIPfullcontact: [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 Channeltype: SIP SIPcallid: dbce2dff-c466daf8-620f38cd@10.11.255.6 SIPfullcontact: [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: build_route: Record-Route hop: [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Session timer started: 206547 - dbce2dff-c466daf8-620f38cd@10.11.255.6 300000ms [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: SIP/origination1.sd-0000028d: New call is still down.... Trying... [Oct 27 15:50:17] DEBUG[1325][C-0000037f] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.11.2.102:5060 [Oct 27 15:50:17] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - origination1.sd [Oct 27 15:50:17] DEBUG[1319] chan_sip.c: Checking device state for peer origination1.sd [Oct 27 15:50:17] DEBUG[1319] devicestate.c: Changing state for SIP/origination1.sd - state 1 (Not in use) [Oct 27 15:50:17] DEBUG[1319] devicestate.c: device 'SIP/origination1.sd' state '1' [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'NoOp' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@subscriber:1] NoOp("SIP/origination1.sd-0000028d", "Subscriber context") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 1 Application: NoOp AppData: Subscriber context Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 1 Application: NoOp AppData: Subscriber context Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Set' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@subscriber:2] Set("SIP/origination1.sd-0000028d", "PSTN=FALSE") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 2 Application: Set AppData: PSTN=FALSE Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 2 Application: Set AppData: PSTN=FALSE Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: PSTN Value: FALSE Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: PSTN Value: FALSE Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Set' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@subscriber:3] Set("SIP/origination1.sd-0000028d", "TRANSFER_CONTEXT=transfer-subscriber") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 3 Application: Set AppData: TRANSFER_CONTEXT=transfer-subscriber Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 3 Application: Set AppData: TRANSFER_CONTEXT=transfer-subscriber Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: TRANSFER_CONTEXT Value: transfer-subscriber Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: TRANSFER_CONTEXT Value: transfer-subscriber Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Gosub' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@subscriber:4] Gosub("SIP/origination1.sd-0000028d", "add-mutehook,s,1") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 4 Application: Gosub AppData: add-mutehook,s,1 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 4 Application: Gosub AppData: add-mutehook,s,1 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] app_stack.c: Channel SIP/origination1.sd-0000028d has no datastore, so we're allocating one. [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Set' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@add-mutehook:1] Set("SIP/origination1.sd-0000028d", "AUDIOHOOK_INHERIT(Mute)=yes") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: add-mutehook Extension: s Priority: 1 Application: Set AppData: AUDIOHOOK_INHERIT(Mute)=yes Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: add-mutehook Extension: s Priority: 1 Application: Set AppData: AUDIOHOOK_INHERIT(Mute)=yes Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] func_audiohookinherit.c: Set audiohook Mute to be inheritable [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Return' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@add-mutehook:2] Return("SIP/origination1.sd-0000028d", "") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: add-mutehook Extension: s Priority: 2 Application: Return AppData: Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: add-mutehook Extension: s Priority: 2 Application: Return AppData: Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: GOSUB_RETVAL Value: Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: GOSUB_RETVAL Value: Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Result of 'EXTEN' is '87' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Goto' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@subscriber:5] Goto("SIP/origination1.sd-0000028d", "deadman,87,1") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 5 Application: Goto AppData: deadman,87,1 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: subscriber Extension: 87 Priority: 5 Application: Goto AppData: deadman,87,1 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Goto (deadman,87,1) [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'NoOp' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@deadman:1] NoOp("SIP/origination1.sd-0000028d", "deadman") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: deadman Extension: 87 Priority: 1 Application: NoOp AppData: deadman Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: deadman Extension: 87 Priority: 1 Application: NoOp AppData: deadman Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Function result is 'sip:2132013013@10.11.2.9' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Set' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@deadman:2] Set("SIP/origination1.sd-0000028d", "SIPFROM=sip:2132013013@10.11.2.9") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: deadman Extension: 87 Priority: 2 Application: Set AppData: SIPFROM=sip:2132013013@10.11.2.9 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: deadman Extension: 87 Priority: 2 Application: Set AppData: SIPFROM=sip:2132013013@10.11.2.9 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPFROM Value: sip:2132013013@10.11.2.9 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: SIPFROM Value: sip:2132013013@10.11.2.9 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Result of 'OfferTimeout' is '60' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Wait' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@deadman:3] Wait("SIP/origination1.sd-0000028d", "60") in new stack [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: deadman Extension: 87 Priority: 3 Application: Wait AppData: 60 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: deadman Extension: 87 Priority: 3 Application: Wait AppData: 60 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Running action 'Redirect' [Oct 27 15:50:17] DEBUG[309] channel.c: Soft-Hanging up channel 'SIP/origination1.sd-0000028d' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Spawn extension (async-agi-loop-fax,87,1) exited non-zero on 'SIP/origination1.sd-0000028d' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: == Spawn extension (async-agi-loop-fax, 87, 1) exited non-zero on 'SIP/origination1.sd-0000028d' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'NoOp' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@async-agi-loop-fax:1] NoOp("SIP/origination1.sd-0000028d", "async-agi-loop") in new stack [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Function result is 'Ring' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Expression result is '0' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'GotoIf' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@async-agi-loop-fax:2] GotoIf("SIP/origination1.sd-0000028d", "0?s,bye") in new stack [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Not taking any branch [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Function result is '0' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Set' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@async-agi-loop-fax:3] Set("SIP/origination1.sd-0000028d", "CALLERID_ANI2=0") in new stack [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Result of 'CONTEXT' is 'async-agi-loop-fax' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Expression result is '1' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'GotoIf' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@async-agi-loop-fax:4] GotoIf("SIP/origination1.sd-0000028d", "1?:async") in new stack [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Not taking any branch [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'Set' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@async-agi-loop-fax:5] Set("SIP/origination1.sd-0000028d", "FAXOPT(faxdetect)=yes") in new stack [Oct 27 15:50:17] DEBUG[14370][C-0000037f] res_fax.c: channel 'SIP/origination1.sd-0000028d' setting FAXOPT(faxdetect) to 'yes' [Oct 27 15:50:17] DEBUG[14370][C-0000037f] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Oct 27 15:50:17] DEBUG[14370][C-0000037f] res_fax.c: Attached FAX detect to channel SIP/origination1.sd-0000028d. [Oct 27 15:50:17] DEBUG[14370][C-0000037f] pbx.c: Launching 'AGI' [Oct 27 15:50:17] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [87@async-agi-loop-fax:6] AGI("SIP/origination1.sd-0000028d", "agi:async") in new stack [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 1 Application: NoOp AppData: async-agi-loop Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 2 Application: GotoIf AppData: 0?s,bye Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 3 Application: Set AppData: CALLERID_ANI2=0 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: CALLERID_ANI2 Value: 0 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 4 Application: GotoIf AppData: 1?:async Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 5 Application: Set AppData: FAXOPT(faxdetect)=yes Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 6 Application: AGI AppData: agi:async Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Forigination1.sd-0000028d%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201414450217.1697%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%202132013013%0Aagi_calleridname%3A%20Alex%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%2087%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20async-agi-loop-fax%0Aagi_extension%3A%2087%0Aagi_priority%3A%206%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068287473408%0A%0A [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 1 Application: NoOp AppData: async-agi-loop Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 2 Application: GotoIf AppData: 0?s,bye Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 3 Application: Set AppData: CALLERID_ANI2=0 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: CALLERID_ANI2 Value: 0 Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 4 Application: GotoIf AppData: 1?:async Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 5 Application: Set AppData: FAXOPT(faxdetect)=yes Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: 87 Priority: 6 Application: AGI AppData: agi:async Uniqueid: 1414450217.1697 [Oct 27 15:50:17] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Forigination1.sd-0000028d%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201414450217.1697%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%202132013013%0Aagi_calleridname%3A%20Alex%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%2087%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20async-agi-loop-fax%0Aagi_extension%3A%2087%0Aagi_priority%3A%206%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068287473408%0A%0A [Oct 27 15:50:18] DEBUG[309] manager.c: Running action 'AGI' [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: SIP answering channel: SIP/origination1.sd-0000028d [Oct 27 15:50:18] DEBUG[14370][C-0000037f] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: Setting framing from config on incoming call [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: ** Our prefcodec: (nothing) [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: -- Done with adding codecs to SDP [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Oct 27 15:50:18] DEBUG[14370][C-0000037f] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.11.2.102:5060 [Oct 27 15:50:18] DEBUG[309] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d CommandId: 940133576 Command: Answer [Oct 27 15:50:18] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450217.1697 [Oct 27 15:50:18] DEBUG[14088] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d CommandId: 940133576 Command: Answer [Oct 27 15:50:18] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450217.1697 [Oct 27 15:50:18] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - origination1.sd [Oct 27 15:50:18] DEBUG[1319] chan_sip.c: Checking device state for peer origination1.sd [Oct 27 15:50:18] DEBUG[1319] devicestate.c: Changing state for SIP/origination1.sd - state 1 (Not in use) [Oct 27 15:50:18] DEBUG[1319] devicestate.c: device 'SIP/origination1.sd' state '1' [Oct 27 15:50:18] DEBUG[1325] chan_sip.c: = Looking for Call ID: dbce2dff-c466daf8-620f38cd@10.11.255.6 (Checking From) --From tag E711C95A-94BFEB27 --To-tag as29970a4f [Oct 27 15:50:18] DEBUG[1325][C-0000037f] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 27 15:50:18] DEBUG[1325][C-0000037f] chan_sip.c: Stopping retransmission on 'dbce2dff-c466daf8-620f38cd@10.11.255.6' of Response 2: Match Found [Oct 27 15:50:18] DEBUG[14370][C-0000037f] res_rtp_asterisk.c: 0x7f6448256a30 -- Probation learning mode pass with source address 10.11.255.6:2266 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.50E+04, Et=2.25E+06, s/n= 0.01 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.50E+04, Et=2.25E+06, s/n= 0.01 [Oct 27 15:50:18] DEBUG[309] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: End Channel: SIP/origination1.sd-0000028d CommandId: 940133576 Command: Answer ResultCode: 200 Result: Success [Oct 27 15:50:18] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Exec Channel: SIP/origination1.sd-0000028d CommandID: 1437091738 Result: 200%20result%3D0%0A [Oct 27 15:50:18] DEBUG[14088] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: End Channel: SIP/origination1.sd-0000028d CommandId: 940133576 Command: Answer ResultCode: 200 Result: Success [Oct 27 15:50:18] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Exec Channel: SIP/origination1.sd-0000028d CommandID: 1437091738 Result: 200%20result%3D0%0A [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.82E+04, Et=3.89E+05, s/n= 0.29 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.79E+04, Et=4.77E+06, s/n= 0.02 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.80E+04, Et=5.62E+06, s/n= 0.02 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.28E+05, Et=4.73E+06, s/n= 0.03 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.20E+04, Et=5.06E+06, s/n= 0.02 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.14E+04, Et=4.84E+06, s/n= 0.02 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.19E+03, Et=4.04E+06, s/n= 0.00 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.77E+04, Et=6.22E+06, s/n= 0.01 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.08E+05, Et=4.22E+06, s/n= 0.03 [Oct 27 15:50:18] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.17E+04, Et=6.16E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.09E+05, Et=7.45E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.25E+03, Et=4.83E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.10E+05, Et=4.76E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.33E+04, Et=4.79E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.49E+04, Et=5.77E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.40E+04, Et=4.65E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.05E+05, Et=4.29E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.69E+04, Et=5.16E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.93E+04, Et=3.59E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.20E+05, Et=7.00E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.19E+05, Et=5.85E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.01E+04, Et=3.35E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.21E+05, Et=4.84E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.38E+05, Et=4.70E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.89E+04, Et=7.22E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.46E+03, Et=6.47E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.20E+05, Et=3.50E+06, s/n= 0.04 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.79E+04, Et=4.35E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.73E+03, Et=5.23E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.10E+05, Et=4.44E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.40E+05, Et=4.93E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.94E+03, Et=4.93E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.75E+04, Et=5.49E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.32E+05, Et=4.26E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.65E+05, Et=5.35E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.08E+04, Et=4.14E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.84E+04, Et=6.04E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.30E+04, Et=5.13E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.22E+05, Et=5.37E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.32E+05, Et=6.46E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.86E+04, Et=4.34E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.27E+05, Et=4.30E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.89E+04, Et=3.49E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.97E+03, Et=5.20E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.13E+04, Et=3.95E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.94E+04, Et=4.71E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.61E+04, Et=4.95E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.02E+05, Et=5.96E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.41E+05, Et=4.77E+06, s/n= 0.05 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.73E+05, Et=4.92E+06, s/n= 0.04 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.09E+04, Et=4.79E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.36E+05, Et=4.74E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.30E+05, Et=4.78E+06, s/n= 0.05 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.48E+05, Et=6.21E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.44E+04, Et=4.79E+06, s/n= 0.01 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.05E+05, Et=4.61E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.70E+04, Et=3.45E+06, s/n= 0.02 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.32E+03, Et=4.23E+06, s/n= 0.00 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.16E+05, Et=3.93E+06, s/n= 0.03 [Oct 27 15:50:19] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.57E+04, Et=4.47E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.70E+04, Et=5.68E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.12E+05, Et=4.90E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.12E+05, Et=4.64E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.21E+05, Et=4.43E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.32E+04, Et=3.81E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.48E+05, Et=4.46E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.19E+04, Et=6.28E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.36E+04, Et=5.13E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.30E+04, Et=3.70E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.05E+04, Et=3.93E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.12E+04, Et=4.24E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.01E+05, Et=5.91E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.42E+04, Et=4.44E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.59E+05, Et=3.38E+06, s/n= 0.05 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.00E+05, Et=5.20E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.39E+04, Et=4.94E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.17E+04, Et=3.84E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.43E+03, Et=5.80E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.26E+04, Et=4.00E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.60E+04, Et=3.57E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.80E+04, Et=5.69E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.17E+04, Et=4.20E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.27E+03, Et=4.70E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.12E+05, Et=4.64E+06, s/n= 0.05 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.32E+05, Et=4.43E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.33E+04, Et=5.06E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.41E+04, Et=3.16E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.46E+04, Et=3.58E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.24E+05, Et=4.33E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.18E+05, Et=5.25E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.74E+05, Et=4.86E+06, s/n= 0.06 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.26E+04, Et=5.48E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.78E+04, Et=5.62E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.54E+04, Et=3.01E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.71E+04, Et=5.03E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.47E+04, Et=4.85E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.02E+04, Et=4.18E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.83E+04, Et=4.68E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.68E+04, Et=4.51E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.02E+05, Et=4.35E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.26E+04, Et=3.80E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.76E+03, Et=3.68E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.11E+05, Et=3.94E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.19E+05, Et=4.02E+06, s/n= 0.03 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.09E+04, Et=5.45E+06, s/n= 0.00 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.27E+05, Et=4.28E+06, s/n= 0.06 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.41E+04, Et=3.94E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.35E+04, Et=3.72E+06, s/n= 0.02 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.62E+04, Et=5.31E+06, s/n= 0.01 [Oct 27 15:50:20] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.17E+05, Et=5.92E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.78E+03, Et=4.28E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.13E+05, Et=3.56E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.96E+03, Et=4.04E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.08E+05, Et=6.07E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.67E+04, Et=4.77E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.62E+03, Et=4.80E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.21E+03, Et=3.41E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.28E+05, Et=3.69E+06, s/n= 0.04 [Oct 27 15:50:21] DEBUG[309] manager.c: Running action 'Setvar' [Oct 27 15:50:21] DEBUG[309] manager.c: Running action 'Originate' [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@redirect-000001af;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: s Context: redirect Uniqueid: 1414450221.1698 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@redirect-000001af;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: AccountCode: Exten: s Context: redirect Uniqueid: 1414450221.1699 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@redirect-000001af;1 Variable: REDIRECT1 Value: SIP/origination1.sd-0000028d,reset-channel,s,1 Uniqueid: 1414450221.1698 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: Local/s@redirect-000001af;1 Uniqueid: 1414450221.1698 AccountCode: OldAccountCode: [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: Local/s@redirect-000001af;1 CallerIDNum: CallerIDName: redirect Uniqueid: 1414450221.1698 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: LocalBridge Privilege: call,all Channel1: Local/s@redirect-000001af;1 Channel2: Local/s@redirect-000001af;2 Uniqueid1: 1414450221.1698 Uniqueid2: 1414450221.1699 Context: redirect Exten: s LocalOptimization: No [Oct 27 15:50:21] DEBUG[14371][C-00000380] pbx.c: Result of 'REDIRECT2' is NULL [Oct 27 15:50:21] DEBUG[14371][C-00000380] pbx.c: Function result is '0' [Oct 27 15:50:21] DEBUG[14371][C-00000380] pbx.c: Expression result is '1' [Oct 27 15:50:21] DEBUG[14371][C-00000380] pbx.c: Launching 'GotoIf' [Oct 27 15:50:21] VERBOSE[14371][C-00000380] pbx.c: -- Executing [s@redirect:1] GotoIf("Local/s@redirect-000001af;2", "1?resetchannel1") in new stack [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@redirect-000001af;2 Context: redirect Extension: s Priority: 1 Application: GotoIf AppData: 1?resetchannel1 Uniqueid: 1414450221.1699 [Oct 27 15:50:21] VERBOSE[14371][C-00000380] pbx.c: -- Goto (redirect,s,3) [Oct 27 15:50:21] DEBUG[14371][C-00000380] pbx.c: Result of 'REDIRECT1' is 'SIP/origination1.sd-0000028d,reset-channel,s,1' [Oct 27 15:50:21] DEBUG[14371][C-00000380] pbx.c: Launching 'ChannelRedirect' [Oct 27 15:50:21] VERBOSE[14371][C-00000380] pbx.c: -- Executing [s@redirect:3] ChannelRedirect("Local/s@redirect-000001af;2", "SIP/origination1.sd-0000028d,reset-channel,s,1") in new stack [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@redirect-000001af;2 Context: redirect Extension: s Priority: 3 Application: ChannelRedirect AppData: SIP/origination1.sd-0000028d,reset-channel,s,1 Uniqueid: 1414450221.1699 [Oct 27 15:50:21] DEBUG[14371][C-00000380] channel.c: Soft-Hanging up channel 'SIP/origination1.sd-0000028d' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] res_agi.c: No frame read on channel SIP/origination1.sd-0000028d, going out ... [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Spawn extension (reset-channel,s,1) exited non-zero on 'SIP/origination1.sd-0000028d' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: == Spawn extension (reset-channel, s, 1) exited non-zero on 'SIP/origination1.sd-0000028d' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Function result is 'Up' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Expression result is '1' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Launching 'GotoIf' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@reset-channel:1] GotoIf("SIP/origination1.sd-0000028d", "1?quiet") in new stack [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Goto (reset-channel,s,4) [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Launching 'Playback' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@reset-channel:4] Playback("SIP/origination1.sd-0000028d", "silence/0") in new stack [Oct 27 15:50:21] DEBUG[14370][C-0000037f] channel.c: Set channel SIP/origination1.sd-0000028d to write format gsm [Oct 27 15:50:21] DEBUG[14370][C-0000037f] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Oct 27 15:50:21] DEBUG[14370][C-0000037f] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] file.c: -- Playing 'silence/0.gsm' (language 'en') [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: End Channel: SIP/origination1.sd-0000028d [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: AGISTATUS Value: HANGUP Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: reset-channel Extension: s Priority: 1 Application: GotoIf AppData: 1?quiet Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: reset-channel Extension: s Priority: 4 Application: Playback AppData: silence/0 Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@redirect-000001af;2 Variable: CHANNELREDIRECT_STATUS Value: SUCCESS Uniqueid: 1414450221.1699 [Oct 27 15:50:21] VERBOSE[14371][C-00000380] pbx.c: -- Auto fallthrough, channel 'Local/s@redirect-000001af;2' status is 'UNKNOWN' [Oct 27 15:50:21] DEBUG[14371][C-00000380] channel.c: Soft-Hanging up channel 'Local/s@redirect-000001af;2' [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Local/s@redirect-000001af;2 Uniqueid: 1414450221.1699 Cause: 16 [Oct 27 15:50:21] DEBUG[14371][C-00000380] channel.c: Hanging up channel 'Local/s@redirect-000001af;2' [Oct 27 15:50:21] DEBUG[309][C-00000380] channel.c: Hanging up channel 'Local/s@redirect-000001af;1' [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@redirect-000001af;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: s Context: redirect Uniqueid: 1414450221.1698 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@redirect-000001af;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: AccountCode: Exten: s Context: redirect Uniqueid: 1414450221.1699 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@redirect-000001af;1 Variable: REDIRECT1 Value: SIP/origination1.sd-0000028d,reset-channel,s,1 Uniqueid: 1414450221.1698 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: Local/s@redirect-000001af;1 Uniqueid: 1414450221.1698 AccountCode: OldAccountCode: [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: Local/s@redirect-000001af;1 CallerIDNum: CallerIDName: redirect Uniqueid: 1414450221.1698 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: LocalBridge Privilege: call,all Channel1: Local/s@redirect-000001af;1 Channel2: Local/s@redirect-000001af;2 Uniqueid1: 1414450221.1698 Uniqueid2: 1414450221.1699 Context: redirect Exten: s LocalOptimization: No [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@redirect-000001af;2 Context: redirect Extension: s Priority: 1 Application: GotoIf AppData: 1?resetchannel1 Uniqueid: 1414450221.1699 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@redirect-000001af;2 Context: redirect Extension: s Priority: 3 Application: ChannelRedirect AppData: SIP/origination1.sd-0000028d,reset-channel,s,1 Uniqueid: 1414450221.1699 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: End Channel: SIP/origination1.sd-0000028d [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: AGISTATUS Value: HANGUP Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: reset-channel Extension: s Priority: 1 Application: GotoIf AppData: 1?quiet Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: reset-channel Extension: s Priority: 4 Application: Playback AppData: silence/0 Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@redirect-000001af;2 Variable: CHANNELREDIRECT_STATUS Value: SUCCESS Uniqueid: 1414450221.1699 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Local/s@redirect-000001af;2 Uniqueid: 1414450221.1699 Cause: 16 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@redirect-000001af;1 Uniqueid: 1414450221.1698 CallerIDNum: CallerIDName: redirect ConnectedLineNum: ConnectedLineName: redirect AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@redirect-000001af;1 Uniqueid: 1414450221.1698 CallerIDNum: CallerIDName: redirect ConnectedLineNum: ConnectedLineName: redirect AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:21] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@redirect [Oct 27 15:50:21] DEBUG[1319] chan_local.c: Checking if extension s@redirect exists (devicestate) [Oct 27 15:50:21] DEBUG[1319] devicestate.c: Changing state for Local/s@redirect - state 1 (Not in use) [Oct 27 15:50:21] DEBUG[1319] devicestate.c: device 'Local/s@redirect' state '1' [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@redirect-000001af;2 Uniqueid: 1414450221.1699 CallerIDNum: CallerIDName: redirect ConnectedLineNum: ConnectedLineName: redirect AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@redirect-000001af;2 Uniqueid: 1414450221.1699 CallerIDNum: CallerIDName: redirect ConnectedLineNum: ConnectedLineName: redirect AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:21] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@redirect [Oct 27 15:50:21] DEBUG[1319] chan_local.c: Checking if extension s@redirect exists (devicestate) [Oct 27 15:50:21] DEBUG[1319] devicestate.c: Changing state for Local/s@redirect - state 1 (Not in use) [Oct 27 15:50:21] DEBUG[1319] devicestate.c: device 'Local/s@redirect' state '1' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.69E+04, Et=5.59E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 27 15:50:21] DEBUG[14370][C-0000037f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 27 15:50:21] DEBUG[14370][C-0000037f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 27 15:50:21] DEBUG[14370][C-0000037f] channel.c: Set channel SIP/origination1.sd-0000028d to write format ulaw [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Launching 'Goto' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@reset-channel:5] Goto("SIP/origination1.sd-0000028d", "async-agi-loop-fax,s,1") in new stack [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Goto (async-agi-loop-fax,s,1) [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Launching 'NoOp' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@async-agi-loop-fax:1] NoOp("SIP/origination1.sd-0000028d", "async-agi-loop-s") in new stack [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Function result is 'Up' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Expression result is '0' [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Launching 'GotoIf' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@async-agi-loop-fax:2] GotoIf("SIP/origination1.sd-0000028d", "0?bye") in new stack [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Not taking any branch [Oct 27 15:50:21] DEBUG[14370][C-0000037f] pbx.c: Launching 'AGI' [Oct 27 15:50:21] VERBOSE[14370][C-0000037f] pbx.c: -- Executing [s@async-agi-loop-fax:3] AGI("SIP/origination1.sd-0000028d", "agi:async") in new stack [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: PLAYBACKSTATUS Value: SUCCESS Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: reset-channel Extension: s Priority: 5 Application: Goto AppData: async-agi-loop-fax,s,1 Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: s Priority: 1 Application: NoOp AppData: async-agi-loop-s Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: s Priority: 2 Application: GotoIf AppData: 0?bye Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: s Priority: 3 Application: AGI AppData: agi:async Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Forigination1.sd-0000028d%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201414450217.1697%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%202132013013%0Aagi_calleridname%3A%20Alex%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%2087%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20async-agi-loop-fax%0Aagi_extension%3A%20s%0Aagi_priority%3A%203%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068287473408%0A%0A [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: PLAYBACKSTATUS Value: SUCCESS Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: reset-channel Extension: s Priority: 5 Application: Goto AppData: async-agi-loop-fax,s,1 Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: s Priority: 1 Application: NoOp AppData: async-agi-loop-s Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: s Priority: 2 Application: GotoIf AppData: 0?bye Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Context: async-agi-loop-fax Extension: s Priority: 3 Application: AGI AppData: agi:async Uniqueid: 1414450217.1697 [Oct 27 15:50:21] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Forigination1.sd-0000028d%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201414450217.1697%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%202132013013%0Aagi_calleridname%3A%20Alex%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%2087%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20async-agi-loop-fax%0Aagi_extension%3A%20s%0Aagi_priority%3A%203%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068287473408%0A%0A [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.54E+04, Et=5.34E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.96E+04, Et=4.98E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.36E+05, Et=5.20E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.98E+04, Et=4.07E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.96E+04, Et=3.34E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.03E+04, Et=4.57E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.12E+04, Et=3.90E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.52E+04, Et=5.67E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.01E+05, Et=6.29E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.86E+04, Et=6.53E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.34E+05, Et=4.88E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.81E+04, Et=3.41E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.03E+04, Et=4.12E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.46E+05, Et=7.42E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.60E+04, Et=4.24E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.13E+05, Et=5.66E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.05E+04, Et=7.60E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.24E+04, Et=5.25E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.86E+04, Et=4.21E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.14E+05, Et=4.38E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.05E+05, Et=3.87E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.70E+04, Et=3.91E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.38E+04, Et=5.30E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.36E+04, Et=3.14E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.83E+04, Et=8.27E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.17E+04, Et=3.81E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.42E+05, Et=3.97E+06, s/n= 0.04 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.96E+05, Et=3.95E+06, s/n= 0.05 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.47E+04, Et=8.39E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.94E+04, Et=3.98E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.18E+04, Et=4.85E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.02E+04, Et=5.12E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.58E+03, Et=5.73E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.14E+04, Et=5.30E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.99E+04, Et=3.81E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.19E+04, Et=3.55E+06, s/n= 0.00 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.08E+05, Et=4.89E+06, s/n= 0.02 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.84E+04, Et=3.49E+06, s/n= 0.03 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.90E+04, Et=7.35E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.62E+04, Et=5.55E+06, s/n= 0.01 [Oct 27 15:50:21] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.33E+04, Et=4.52E+06, s/n= 0.02 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.12E+05, Et=6.45E+06, s/n= 0.02 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.22E+04, Et=8.24E+06, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.14E+04, Et=5.10E+06, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.29E+05, Et=6.65E+06, s/n= 0.02 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.31E+05, Et=5.35E+06, s/n= 0.03 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.28E+04, Et=5.43E+06, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.55E+04, Et=4.10E+06, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.33E+04, Et=5.03E+06, s/n= 0.02 [Oct 27 15:50:22] DEBUG[309] manager.c: Running action 'AGI' [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.51E+04, Et=4.44E+06, s/n= 0.02 [Oct 27 15:50:22] DEBUG[309] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d CommandId: 17552001 Command: EXEC MusicOnHold [Oct 27 15:50:22] DEBUG[14088] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: Start Channel: SIP/origination1.sd-0000028d CommandId: 17552001 Command: EXEC MusicOnHold [Oct 27 15:50:22] VERBOSE[14370][C-0000037f] res_agi.c: -- AGI Script Executing Application: (MusicOnHold) Options: () [Oct 27 15:50:22] DEBUG[309] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Start Channel: SIP/origination1.sd-0000028d UniqueID: 1414450217.1697 Class: default [Oct 27 15:50:22] DEBUG[14088] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Start Channel: SIP/origination1.sd-0000028d UniqueID: 1414450217.1697 Class: default [Oct 27 15:50:22] VERBOSE[14370][C-0000037f] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/origination1.sd-0000028d [Oct 27 15:50:22] DEBUG[14370][C-0000037f] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.78E+05, Et=4.83E+06, s/n= 0.04 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] channel.c: Generator got voice, switching to phase locked mode [Oct 27 15:50:22] DEBUG[14370][C-0000037f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 27 15:50:22] NOTICE[14370][C-0000037f] res_musiconhold.c: Using musicfile override /opt/tmp/IProvider/music/c180e6ad-edd7-4f3e-a960-ca840def6df6 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] res_musiconhold.c: File selected by musicfile override exists [Oct 27 15:50:22] DEBUG[14370][C-0000037f] channel.c: Set channel SIP/origination1.sd-0000028d to write format adpcm [Oct 27 15:50:22] DEBUG[14370][C-0000037f] res_musiconhold.c: SIP/origination1.sd-0000028d Opened file 0 '/opt/tmp/IProvider/music/c180e6ad-edd7-4f3e-a960-ca840def6df6' [Oct 27 15:50:22] DEBUG[14370][C-0000037f] res_rtp_asterisk.c: Difference is 8096, ms is 1032 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.55E+03, Et=5.53E+06, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.00E+05, Et=1.97E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.66E+06, Et=1.49E+09, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.48E+06, Et=5.05E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.93E+06, Et=4.74E+08, s/n= 0.02 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.68E+06, Et=9.86E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.06E+06, Et=1.42E+09, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.31E+05, Et=1.32E+09, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.84E+05, Et=1.85E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.61E+05, Et=1.84E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.94E+05, Et=4.63E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.88E+04, Et=5.49E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.41E+05, Et=2.25E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.72E+05, Et=1.29E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.55E+04, Et=1.13E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.47E+06, Et=2.49E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.14E+05, Et=2.22E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.00E+05, Et=1.57E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.83E+06, Et=1.77E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.74E+05, Et=1.09E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.89E+05, Et=2.07E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.54E+05, Et=1.36E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.67E+05, Et=1.06E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.08E+05, Et=4.27E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.96E+05, Et=4.30E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.60E+06, Et=1.12E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.27E+05, Et=6.70E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.37E+04, Et=1.11E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.99E+05, Et=8.44E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.57E+05, Et=1.30E+08, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.05E+04, Et=2.25E+08, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.09E+05, Et=7.02E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.16E+05, Et=3.31E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.52E+05, Et=5.54E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.70E+05, Et=6.29E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.54E+05, Et=4.98E+07, s/n= 0.01 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.84E+02, Et=3.77E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.76E+05, Et=4.42E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.16E+05, Et=5.51E+07, s/n= 0.00 [Oct 27 15:50:22] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.23E+04, Et=4.27E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.27E+05, Et=4.03E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.06E+04, Et=3.79E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.66E+05, Et=5.11E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.31E+05, Et=4.32E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.28E+05, Et=4.34E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.95E+04, Et=5.34E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.57E+04, Et=2.44E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.88E+05, Et=2.51E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.49E+05, Et=3.12E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.22E+04, Et=3.17E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.07E+05, Et=5.85E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.77E+06, Et=1.53E+08, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.45E+05, Et=1.29E+08, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.08E+05, Et=1.43E+08, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.78E+04, Et=1.34E+08, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.77E+04, Et=1.12E+08, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.58E+05, Et=6.69E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.60E+05, Et=6.39E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.79E+05, Et=6.27E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.08E+05, Et=6.56E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[309] manager.c: Running action 'Originate' [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@originate-000001b0;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: s Context: originate Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@originate-000001b0;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: AccountCode: Exten: s Context: originate Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION_NAME_B64 Value: TWFyaw== Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION Value: 1 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: _RECORDFILE Value: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: CPBX_AUTOANSWER Value: FALSE Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: OFFER_ID Value: 5495befb-35f1-4f7c-99f7-e5d9325994e0 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: Local/s@originate-000001b0;1 Uniqueid: 1414450223.1700 AccountCode: OldAccountCode: [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: Local/s@originate-000001b0;1 CallerIDNum: 81 CallerIDName: John Fst2 Uniqueid: 1414450223.1700 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: LocalBridge Privilege: call,all Channel1: Local/s@originate-000001b0;1 Channel2: Local/s@originate-000001b0;2 Uniqueid1: 1414450223.1700 Uniqueid2: 1414450223.1701 Context: originate Exten: s LocalOptimization: No [Oct 27 15:50:23] DEBUG[14372][C-00000381] pbx.c: Launching 'Answer' [Oct 27 15:50:23] VERBOSE[14372][C-00000381] pbx.c: -- Executing [s@originate:1] Answer("Local/s@originate-000001b0;2", "") in new stack [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;2 Context: originate Extension: s Priority: 1 Application: Answer AppData: Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@originate-000001b0;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: s Context: originate Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Local/s@originate-000001b0;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: AccountCode: Exten: s Context: originate Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION_NAME_B64 Value: TWFyaw== Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION Value: 1 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: _RECORDFILE Value: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: CPBX_AUTOANSWER Value: FALSE Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: OFFER_ID Value: 5495befb-35f1-4f7c-99f7-e5d9325994e0 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: Local/s@originate-000001b0;1 Uniqueid: 1414450223.1700 AccountCode: OldAccountCode: [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: Local/s@originate-000001b0;1 CallerIDNum: 81 CallerIDName: John Fst2 Uniqueid: 1414450223.1700 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: LocalBridge Privilege: call,all Channel1: Local/s@originate-000001b0;1 Channel2: Local/s@originate-000001b0;2 Uniqueid1: 1414450223.1700 Uniqueid2: 1414450223.1701 Context: originate Exten: s LocalOptimization: No [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;2 Context: originate Extension: s Priority: 1 Application: Answer AppData: Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Local/s@originate-000001b0;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@originate [Oct 27 15:50:23] DEBUG[1319] chan_local.c: Checking if extension s@originate exists (devicestate) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: Changing state for Local/s@originate - state 2 (In use) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: device 'Local/s@originate' state '2' [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Local/s@originate-000001b0;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@originate [Oct 27 15:50:23] DEBUG[1319] chan_local.c: Checking if extension s@originate exists (devicestate) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: Changing state for Local/s@originate - state 2 (In use) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: device 'Local/s@originate' state '2' [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Local/s@originate-000001b0;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Local/s@originate-000001b0;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[14372][C-00000381] chan_local.c: Blocked indication -1 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:1] NoOp("Local/s@originate-000001b0;1", "Dialing") in new stack [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.93E+05, Et=5.51E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 1 Application: NoOp AppData: Dialing Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 1 Application: NoOp AppData: Dialing Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'EXTEN' is '47609336033' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '0' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'EXTEN' is '47609336033' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:2] GotoIf("Local/s@originate-000001b0;1", "0?dial-n11,47609336033,1") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 2 Application: GotoIf AppData: 0?dial-n11,47609336033,1 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 2 Application: GotoIf AppData: 0?dial-n11,47609336033,1 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Not taking any branch [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'FVS_DIVERSION' is '1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GosubIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:3] GosubIf("Local/s@originate-000001b0;1", "1?sub-diversion-header,diversion,1") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 3 Application: GosubIf AppData: 1?sub-diversion-header,diversion,1 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 3 Application: GosubIf AppData: 1?sub-diversion-header,diversion,1 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] app_stack.c: Channel Local/s@originate-000001b0;1 has no datastore, so we're allocating one. [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:1] NoOp("Local/s@originate-000001b0;1", "") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 1 Application: NoOp AppData: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 1 Application: NoOp AppData: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'FVS_DIVERSION_NAME_B64' is 'TWFyaw==' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Function result is 'Mark' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'Set' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:2] Set("Local/s@originate-000001b0;1", "FVS_DIVERSION_NAME=Mark") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 2 Application: Set AppData: FVS_DIVERSION_NAME=Mark Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 2 Application: Set AppData: FVS_DIVERSION_NAME=Mark Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION_NAME Value: Mark Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION_NAME Value: Mark Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'FVS_DIVERSION_NUMBER_B64' is NULL [Oct 27 15:50:23] WARNING[14373][C-00000381] func_base64.c: Syntax: BASE64_DECODE() - missing argument! [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Function result is '(null)' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'Set' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:3] Set("Local/s@originate-000001b0;1", "FVS_DIVERSION_NUMBER=") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 3 Application: Set AppData: FVS_DIVERSION_NUMBER= Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 3 Application: Set AppData: FVS_DIVERSION_NUMBER= Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION_NUMBER Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: FVS_DIVERSION_NUMBER Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Function result is 'John Fst2' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:4] GotoIf("Local/s@originate-000001b0;1", "1?set-diversion") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 4 Application: GotoIf AppData: 1?set-diversion Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 4 Application: GotoIf AppData: 1?set-diversion Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (sub-diversion-header,diversion,6) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'FVS_DIVERSION_NAME' is 'Mark' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '0' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:6] GotoIf("Local/s@originate-000001b0;1", "0?number:name") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 6 Application: GotoIf AppData: 0?number:name Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 6 Application: GotoIf AppData: 0?number:name Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (sub-diversion-header,diversion,9) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'FVS_DIVERSION_NAME' is 'Mark' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'FVS_DIVERSION_NUMBER' is '' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'SIPAddHeader' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:9] SIPAddHeader("Local/s@originate-000001b0;1", "Diversion: "Mark" ;reason=unconditional") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 9 Application: SIPAddHeader AppData: Diversion: "Mark" ;reason=unconditional Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 9 Application: SIPAddHeader AppData: Diversion: "Mark" ;reason=unconditional Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: __SIPADDHEADER01 Value: Diversion: "Mark" ;reason=unconditional Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: __SIPADDHEADER01 Value: Diversion: "Mark" ;reason=unconditional Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'Return' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [diversion@sub-diversion-header:10] Return("Local/s@originate-000001b0;1", "") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 10 Application: Return AppData: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: sub-diversion-header Extension: diversion Priority: 10 Application: Return AppData: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: GOSUB_RETVAL Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: GOSUB_RETVAL Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Function result is '81' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:4] GotoIf("Local/s@originate-000001b0;1", "1 ?skip-calleridnumset") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 4 Application: GotoIf AppData: 1 ?skip-calleridnumset Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 4 Application: GotoIf AppData: 1 ?skip-calleridnumset Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (dial,47609336033,6) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'CPBX_AUTOANSWER' is 'FALSE' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '0' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:6] GotoIf("Local/s@originate-000001b0;1", "0?auto:noauto") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 6 Application: GotoIf AppData: 0?auto:noauto Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 6 Application: GotoIf AppData: 0?auto:noauto Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (dial,47609336033,10) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'SIPRemoveHeader' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:10] SIPRemoveHeader("Local/s@originate-000001b0;1", "Call-Info: <>;answer-after=0") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 10 Application: SIPRemoveHeader AppData: Call-Info: <>;answer-after=0 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 10 Application: SIPRemoveHeader AppData: Call-Info: <>;answer-after=0 Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'SIPRemoveHeader' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:11] SIPRemoveHeader("Local/s@originate-000001b0;1", "Alert-Info: Ring Answer") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 11 Application: SIPRemoveHeader AppData: Alert-Info: Ring Answer Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 11 Application: SIPRemoveHeader AppData: Alert-Info: Ring Answer Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:12] NoOp("Local/s@originate-000001b0;1", "Done with Auto-Answer") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 12 Application: NoOp AppData: Done with Auto-Answer Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 12 Application: NoOp AppData: Done with Auto-Answer Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'SIPTRANSFER_REPLACES' is NULL [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:13] GotoIf("Local/s@originate-000001b0;1", "1?noreplaces") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 13 Application: GotoIf AppData: 1?noreplaces Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 13 Application: GotoIf AppData: 1?noreplaces Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (dial,47609336033,16) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'TARGET_SIP_ENDPOINT' is NULL [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Function result is '0' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '0' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:16] GotoIf("Local/s@originate-000001b0;1", "0?targetted:notarget") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 16 Application: GotoIf AppData: 0?targetted:notarget Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 16 Application: GotoIf AppData: 0?targetted:notarget Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (dial,47609336033,19) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'EXTEN' is '47609336033' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'Set' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:19] Set("Local/s@originate-000001b0;1", "SIPDIALSTRING=SIP/7609336033@termination1.sd") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 19 Application: Set AppData: SIPDIALSTRING=SIP/7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 19 Application: Set AppData: SIPDIALSTRING=SIP/7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: SIPDIALSTRING Value: SIP/7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: SIPDIALSTRING Value: SIP/7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'SIPDIALSTRING' is 'SIP/7609336033@termination1.sd' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:20] NoOp("Local/s@originate-000001b0;1", "Dial String is SIP/7609336033@termination1.sd") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 20 Application: NoOp AppData: Dial String is SIP/7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 20 Application: NoOp AppData: Dial String is SIP/7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'CHANNEL' is 'Local/s@originate-000001b0;1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Expression result is '6' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:21] GotoIf("Local/s@originate-000001b0;1", "6?originate:singlestepconf") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 21 Application: GotoIf AppData: 6?originate:singlestepconf Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 21 Application: GotoIf AppData: 6?originate:singlestepconf Uniqueid: 1414450223.1700 [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Goto (dial,47609336033,22) [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:22] NoOp("Local/s@originate-000001b0;1", "Originate-to-CloudPBX") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 22 Application: NoOp AppData: Originate-to-CloudPBX Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 22 Application: NoOp AppData: Originate-to-CloudPBX Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Result of 'SIPDIALSTRING' is 'SIP/7609336033@termination1.sd' [Oct 27 15:50:23] DEBUG[14373][C-00000381] pbx.c: Launching 'Dial' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] pbx.c: -- Executing [47609336033@dial:23] Dial("Local/s@originate-000001b0;1", "SIP/7609336033@termination1.sd,,G(post-originate^s^1)") in new stack [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 23 Application: Dial AppData: SIP/7609336033@termination1.sd,,G(post-originate^s^1) Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: dial Extension: 47609336033 Priority: 23 Application: Dial AppData: SIP/7609336033@termination1.sd,,G(post-originate^s^1) Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALSTATUS Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALSTATUS Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNUMBER Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNUMBER Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNAME Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNAME Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: ANSWEREDTIME Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: ANSWEREDTIME Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDTIME Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDTIME Value: Uniqueid: 1414450223.1700 [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Asked to create a SIP channel with formats: (slin) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Allocating new SIP dialog for 31705e9a6ba27269681587e4091ce8bb@10.11.2.232:5060 - INVITE (No RTP) [Oct 27 15:50:23] DEBUG[14373][C-00000381] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f644c21df08' [Oct 27 15:50:23] DEBUG[14373][C-00000381] res_rtp_asterisk.c: Allocated port 16230 for RTP instance '0x7f644c21df08' [Oct 27 15:50:23] DEBUG[14373][C-00000381] rtp_engine.c: RTP instance '0x7f644c21df08' is setup and ready to go [Oct 27 15:50:23] DEBUG[14373][C-00000381] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f644c21df08' [Oct 27 15:50:23] VERBOSE[14373][C-00000381] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Setting NAT on RTP to On [Oct 27 15:50:23] DEBUG[14373][C-00000381] acl.c: For destination '10.11.2.151', our source address is '10.11.2.232'. [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Setting NAT on RTP to On [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: SIP call-id changed from '31705e9a6ba27269681587e4091ce8bb@10.11.2.232:5060' to '13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060' [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/termination1.sd-0000028e ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: Context: subscriber Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/termination1.sd-0000028e ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: Context: subscriber Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: *** Our native formats are (ulaw) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: *** Joint capabilities are (nothing) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: *** Our capabilities are (ulaw) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: *** Our preferred formats from the incoming channel are (slin) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: This channel will not be able to handle video. [Oct 27 15:50:23] DEBUG[14373][C-00000381] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Oct 27 15:50:23] DEBUG[14373][C-00000381] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: SIPCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: SIPCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/termination1.sd-0000028e Uniqueid: 1414450223.1702 Channeltype: SIP SIPcallid: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 SIPfullcontact: [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/termination1.sd-0000028e Uniqueid: 1414450223.1702 Channeltype: SIP SIPcallid: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 SIPfullcontact: [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/termination1.sd-0000028e Channeltype: SIP SIPcallid: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 SIPfullcontact: Peername: termination1.sd [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/termination1.sd-0000028e Channeltype: SIP SIPcallid: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 SIPfullcontact: Peername: termination1.sd [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel_internal_api.c: Channel Call ID changing from [C-00000381] to [C-00000381] [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: DIALEDPEERNUMBER Value: 7609336033@termination1.sd Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: DIALEDPEERNUMBER Value: 7609336033@termination1.sd Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[14373][C-00000381] rtp_engine.c: Can't find native functions for channel 'Local/s@originate-000001b0;1' [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable DIALEDTIME. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable ANSWEREDTIME. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable DIALEDPEERNAME. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable DIALEDPEERNUMBER. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable DIALSTATUS. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable SIPDIALSTRING. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable GOSUB_RETVAL. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Copying hard-transferable variable SIPADDHEADER01. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable FVS_DIVERSION_NUMBER. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable FVS_DIVERSION_NAME. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable OFFER_ID. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable CPBX_AUTOANSWER. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Copying soft-transferable variable RECORDFILE. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable FVS_DIVERSION. [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Not copying variable FVS_DIVERSION_NAME_B64. [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/termination1.sd-0000028e CallerIDNum: 47609336033 CallerIDName: John Fst2 Uniqueid: 1414450223.1702 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/termination1.sd-0000028e CallerIDNum: 47609336033 CallerIDName: John Fst2 Uniqueid: 1414450223.1702 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Outgoing Call for 7609336033 [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Updating call counter for outgoing call [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: ** Our prefcodec: (slin) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: -- Done with adding codecs to SDP [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Initializing initreq for method INVITE - callid 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 [Oct 27 15:50:23] DEBUG[14373][C-00000381] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.11.2.151:5060 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.83E+05, Et=4.42E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[1325] chan_sip.c: = Looking for Call ID: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 (Checking To) --From tag as6021fe8c --To-tag [Oct 27 15:50:23] DEBUG[1325][C-00000381] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060' Request 102: Found [Oct 27 15:50:23] DEBUG[1325][C-00000381] chan_sip.c: SIP response 100 to standard invite [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: Begin Channel: Local/s@originate-000001b0;1 Destination: SIP/termination1.sd-0000028e CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 UniqueID: 1414450223.1700 DestUniqueID: 1414450223.1702 Dialstring: 7609336033@termination1.sd [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: Begin Channel: Local/s@originate-000001b0;1 Destination: SIP/termination1.sd-0000028e CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 UniqueID: 1414450223.1700 DestUniqueID: 1414450223.1702 Dialstring: 7609336033@termination1.sd [Oct 27 15:50:23] VERBOSE[14373][C-00000381] app_dial.c: -- Called SIP/7609336033@termination1.sd [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Set channel SIP/termination1.sd-0000028e to read format slin [Oct 27 15:50:23] DEBUG[14373][C-00000381] channel.c: Set channel SIP/termination1.sd-0000028e to write format slin [Oct 27 15:50:23] DEBUG[14370][C-0000037f] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.21E+05, Et=4.16E+07, s/n= 0.02 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.87E+04, Et=2.94E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.62E+05, Et=3.13E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[1325] chan_sip.c: = Looking for Call ID: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 (Checking To) --From tag as6021fe8c --To-tag 499F9362-25D9BE0F [Oct 27 15:50:23] DEBUG[1325][C-00000381] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060' Request 102: Found [Oct 27 15:50:23] DEBUG[1325][C-00000381] chan_sip.c: SIP response 180 to standard invite [Oct 27 15:50:23] DEBUG[1325][C-00000381] chan_sip.c: build_route: Record-Route hop: [Oct 27 15:50:23] VERBOSE[14373][C-00000381] app_dial.c: -- SIP/termination1.sd-0000028e is ringing [Oct 27 15:50:23] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - termination1.sd [Oct 27 15:50:23] DEBUG[1319] chan_sip.c: Checking device state for peer termination1.sd [Oct 27 15:50:23] DEBUG[1319] devicestate.c: Changing state for SIP/termination1.sd - state 1 (Not in use) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: device 'SIP/termination1.sd' state '1' [Oct 27 15:50:23] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@originate [Oct 27 15:50:23] DEBUG[1319] chan_local.c: Checking if extension s@originate exists (devicestate) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: Changing state for Local/s@originate - state 2 (In use) [Oct 27 15:50:23] DEBUG[1319] devicestate.c: device 'Local/s@originate' state '2' [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/termination1.sd-0000028e ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 47609336033 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Local/s@originate-000001b0;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/termination1.sd-0000028e ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 47609336033 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1702 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Local/s@originate-000001b0;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.19E+05, Et=2.83E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.25E+05, Et=2.99E+07, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.83E+05, Et=7.31E+07, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.12E+06, Et=7.53E+07, s/n= 0.02 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.31E+05, Et=2.13E+08, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.35E+06, Et=1.48E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.27E+06, Et=1.73E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.43E+06, Et=1.52E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.46E+07, Et=1.54E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.21E+06, Et=1.35E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.82E+08, Et=2.10E+10, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.60E+08, Et=2.58E+10, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.13E+08, Et=2.33E+10, s/n= 0.02 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.30E+08, Et=2.48E+10, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.12E+08, Et=1.80E+10, s/n= 0.02 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.62E+06, Et=1.52E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.65E+07, Et=1.56E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.31E+06, Et=1.47E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.65E+07, Et=1.44E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.77E+06, Et=1.25E+10, s/n= 0.00 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.66E+08, Et=2.02E+10, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14372][C-00000381] channel.c: Didn't receive a media frame from Local/s@originate-000001b0;2 within 500 ms of answering. Continuing anyway [Oct 27 15:50:23] DEBUG[14372][C-00000381] pbx.c: Launching 'AGI' [Oct 27 15:50:23] VERBOSE[14372][C-00000381] pbx.c: -- Executing [s@originate:2] AGI("Local/s@originate-000001b0;2", "agi:async") in new stack [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;2 Context: originate Extension: s Priority: 2 Application: AGI AppData: agi:async Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: Local/s@originate-000001b0;2 Env: agi_request%3A%20async%0Aagi_channel%3A%20Local%2Fs%40originate-000001b0%3B2%0Aagi_language%3A%20en%0Aagi_type%3A%20Local%0Aagi_uniqueid%3A%201414450223.1701%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%2081%0Aagi_calleridname%3A%20John%20Fst2%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20originate%0Aagi_extension%3A%20s%0Aagi_priority%3A%202%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068283410176%0A%0A [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;2 Context: originate Extension: s Priority: 2 Application: AGI AppData: agi:async Uniqueid: 1414450223.1701 [Oct 27 15:50:23] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: Local/s@originate-000001b0;2 Env: agi_request%3A%20async%0Aagi_channel%3A%20Local%2Fs%40originate-000001b0%3B2%0Aagi_language%3A%20en%0Aagi_type%3A%20Local%0Aagi_uniqueid%3A%201414450223.1701%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%2081%0Aagi_calleridname%3A%20John%20Fst2%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20originate%0Aagi_extension%3A%20s%0Aagi_priority%3A%202%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068283410176%0A%0A [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.52E+08, Et=2.70E+10, s/n= 0.02 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.74E+08, Et=2.46E+10, s/n= 0.02 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.42E+08, Et=2.41E+10, s/n= 0.01 [Oct 27 15:50:23] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.54E+08, Et=1.93E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.21E+06, Et=1.55E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.86E+07, Et=1.84E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.14E+08, Et=2.39E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.50E+07, Et=1.86E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.58E+06, Et=1.64E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.50E+08, Et=2.40E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.92E+08, Et=3.10E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.05E+09, Et=2.60E+10, s/n= 0.04 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.30E+08, Et=2.83E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.86E+08, Et=2.19E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.30E+06, Et=2.01E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.80E+07, Et=2.02E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.28E+07, Et=1.88E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.39E+07, Et=1.79E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.82E+06, Et=1.54E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.77E+08, Et=2.39E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.94E+08, Et=3.08E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.07E+08, Et=2.61E+10, s/n= 0.03 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.92E+08, Et=2.68E+10, s/n= 0.01 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.91E+08, Et=2.05E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.21E+06, Et=1.77E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.44E+07, Et=1.95E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=7.07E+06, Et=1.75E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.74E+07, Et=1.78E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.55E+07, Et=1.42E+10, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.44E+08, Et=2.29E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=6.54E+08, Et=2.92E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.81E+08, Et=2.56E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.55E+08, Et=2.62E+10, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=8.28E+07, Et=9.68E+09, s/n= 0.01 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.51E+05, Et=5.44E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.06E+06, Et=3.05E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.59E+05, Et=2.43E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[1325] chan_sip.c: = Looking for Call ID: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 (Checking To) --From tag as6021fe8c --To-tag 499F9362-25D9BE0F [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Acked pending invite 102 [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Stopping retransmission on '13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060' of Request 102: Match Found [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: SIP response 200 to standard invite [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing session-level SDP o=- 1414450223 1414450223 IN IP4 10.11.255.1... OK. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED OR FAILED. [Oct 27 15:50:24] DEBUG[1325][C-00000381] netsock2.c: Splitting '10.11.255.1' into... [Oct 27 15:50:24] DEBUG[1325][C-00000381] netsock2.c: ...host '10.11.255.1' and port ''. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing session-level SDP c=IN IP4 10.11.255.1... OK. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing session-level SDP a=sendrecv... OK. [Oct 27 15:50:24] DEBUG[1325][C-00000381] rtp_engine.c: Setting payload 0 based on m type on 0x7f64381ca3d0 [Oct 27 15:50:24] DEBUG[1325][C-00000381] rtp_engine.c: Setting payload 101 based on m type on 0x7f64381ca3d0 [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Oct 27 15:50:24] DEBUG[1325][C-00000381] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f644c21df08' [Oct 27 15:50:24] DEBUG[1325][C-00000381] rtp_engine.c: Copying payload 0 from 0x7f64381ca3d0 to 0x7f644c21e0d0 [Oct 27 15:50:24] DEBUG[1325][C-00000381] rtp_engine.c: Copying payload 101 from 0x7f64381ca3d0 to 0x7f644c21e0d0 [Oct 27 15:50:24] DEBUG[1325][C-00000381] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f644c21df08' [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: We're settling with these formats: (ulaw) [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: We have an owner, now see if we need to change this call [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Updating call counter for outgoing call [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: build_route: Record-Route hop: [Oct 27 15:50:24] DEBUG[1325][C-00000381] netsock2.c: Splitting '10.11.255.1:5060' into... [Oct 27 15:50:24] DEBUG[1325][C-00000381] netsock2.c: ...host '10.11.255.1' and port '5060'. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Session timer started: 206553 - 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 300000ms [Oct 27 15:50:24] DEBUG[1325][C-00000381] netsock2.c: Splitting '10.11.2.9' into... [Oct 27 15:50:24] DEBUG[1325][C-00000381] netsock2.c: ...host '10.11.2.9' and port ''. [Oct 27 15:50:24] DEBUG[1325][C-00000381] chan_sip.c: Trying to put 'ACK sip:760' onto UDP socket destined for 10.11.2.9:5060 [Oct 27 15:50:24] VERBOSE[14373][C-00000381] app_dial.c: -- SIP/termination1.sd-0000028e answered Local/s@originate-000001b0;1 [Oct 27 15:50:24] DEBUG[14373][C-00000381] pbx.c: Launching 'Hangup' [Oct 27 15:50:24] VERBOSE[14373][C-00000381] pbx.c: -- Executing [s@post-originate:1] Hangup("Local/s@originate-000001b0;1", "") in new stack [Oct 27 15:50:24] DEBUG[14373][C-00000381] channel.c: Soft-Hanging up channel 'Local/s@originate-000001b0;1' [Oct 27 15:50:24] DEBUG[14373][C-00000381] pbx.c: Spawn extension (post-originate,s,1) exited non-zero on 'Local/s@originate-000001b0;1' [Oct 27 15:50:24] VERBOSE[14373][C-00000381] pbx.c: == Spawn extension (post-originate, s, 1) exited non-zero on 'Local/s@originate-000001b0;1' [Oct 27 15:50:24] DEBUG[14373][C-00000381] channel.c: Soft-Hanging up channel 'Local/s@originate-000001b0;1' [Oct 27 15:50:24] DEBUG[14373][C-00000381] channel.c: Hanging up channel 'Local/s@originate-000001b0;1' [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/termination1.sd-0000028e Channeltype: SIP Uniqueid: 1414450223.1702 SIPcallid: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 SIPfullcontact: sip:7609336033@10.11.255.1:5060 Peername: termination1.sd [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/termination1.sd-0000028e ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 47609336033 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALSTATUS Value: ANSWER Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNAME Value: SIP/termination1.sd-0000028e Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNUMBER Value: 7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: post-originate Extension: s Priority: 1 Application: Hangup AppData: Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Local/s@originate-000001b0;1 Uniqueid: 1414450223.1700 Cause: 16 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: HangupRequest Privilege: call,all Channel: Local/s@originate-000001b0;2 Uniqueid: 1414450223.1701 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@originate-000001b0;1 Uniqueid: 1414450223.1700 CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 AccountCode: Cause: 16 Cause-txt: Normal Clearing [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/termination1.sd-0000028e Channeltype: SIP Uniqueid: 1414450223.1702 SIPcallid: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 SIPfullcontact: sip:7609336033@10.11.255.1:5060 Peername: termination1.sd [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/termination1.sd-0000028e ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 47609336033 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALSTATUS Value: ANSWER Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNAME Value: SIP/termination1.sd-0000028e Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Variable: DIALEDPEERNUMBER Value: 7609336033@termination1.sd Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: Local/s@originate-000001b0;1 Context: post-originate Extension: s Priority: 1 Application: Hangup AppData: Uniqueid: 1414450223.1700 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Local/s@originate-000001b0;1 Uniqueid: 1414450223.1700 Cause: 16 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: HangupRequest Privilege: call,all Channel: Local/s@originate-000001b0;2 Uniqueid: 1414450223.1701 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@originate-000001b0;1 Uniqueid: 1414450223.1700 CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 AccountCode: Cause: 16 Cause-txt: Normal Clearing [Oct 27 15:50:24] DEBUG[14372][C-00000381] res_agi.c: No frame read on channel Local/s@originate-000001b0;2, going out ... [Oct 27 15:50:24] DEBUG[14372][C-00000381] pbx.c: Spawn extension (originate,s,2) exited non-zero on 'Local/s@originate-000001b0;2' [Oct 27 15:50:24] VERBOSE[14372][C-00000381] pbx.c: == Spawn extension (originate, s, 2) exited non-zero on 'Local/s@originate-000001b0;2' [Oct 27 15:50:24] DEBUG[14372][C-00000381] channel.c: Soft-Hanging up channel 'Local/s@originate-000001b0;2' [Oct 27 15:50:24] DEBUG[14372][C-00000381] channel.c: Hanging up channel 'Local/s@originate-000001b0;2' [Oct 27 15:50:24] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - termination1.sd [Oct 27 15:50:24] DEBUG[1319] chan_sip.c: Checking device state for peer termination1.sd [Oct 27 15:50:24] DEBUG[1319] devicestate.c: Changing state for SIP/termination1.sd - state 1 (Not in use) [Oct 27 15:50:24] DEBUG[1319] devicestate.c: device 'SIP/termination1.sd' state '1' [Oct 27 15:50:24] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@originate [Oct 27 15:50:24] DEBUG[1319] chan_local.c: Checking if extension s@originate exists (devicestate) [Oct 27 15:50:24] DEBUG[1319] devicestate.c: Changing state for Local/s@originate - state 2 (In use) [Oct 27 15:50:24] DEBUG[1319] devicestate.c: device 'Local/s@originate' state '2' [Oct 27 15:50:24] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Local - s@originate [Oct 27 15:50:24] DEBUG[1319] chan_local.c: Checking if extension s@originate exists (devicestate) [Oct 27 15:50:24] DEBUG[1319] devicestate.c: Changing state for Local/s@originate - state 2 (In use) [Oct 27 15:50:24] DEBUG[1319] devicestate.c: device 'Local/s@originate' state '2' [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: End Channel: Local/s@originate-000001b0;2 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;2 Variable: AGISTATUS Value: HANGUP Uniqueid: 1414450223.1701 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Local/s@originate-000001b0;2 Uniqueid: 1414450223.1701 Cause: 16 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@originate-000001b0;2 Uniqueid: 1414450223.1701 CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: End Channel: Local/s@originate-000001b0;2 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Local/s@originate-000001b0;2 Variable: AGISTATUS Value: HANGUP Uniqueid: 1414450223.1701 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Local/s@originate-000001b0;2 Uniqueid: 1414450223.1701 Cause: 16 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Local/s@originate-000001b0;2 Uniqueid: 1414450223.1701 CallerIDNum: 81 CallerIDName: John Fst2 ConnectedLineNum: 81 ConnectedLineName: John Fst2 AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Result of 'RECORDFILE' is '/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@post-originate:2] NoOp("SIP/termination1.sd-0000028e", "RecordFile = /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 2 Application: NoOp AppData: RecordFile = /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 2 Application: NoOp AppData: RecordFile = /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'Gosub' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@post-originate:3] Gosub("SIP/termination1.sd-0000028e", "add-mutehook,s,1") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 3 Application: Gosub AppData: add-mutehook,s,1 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 3 Application: Gosub AppData: add-mutehook,s,1 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] app_stack.c: Channel SIP/termination1.sd-0000028e has no datastore, so we're allocating one. [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: LOCAL(ARGC) Value: 0 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'Set' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@add-mutehook:1] Set("SIP/termination1.sd-0000028e", "AUDIOHOOK_INHERIT(Mute)=yes") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: add-mutehook Extension: s Priority: 1 Application: Set AppData: AUDIOHOOK_INHERIT(Mute)=yes Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: add-mutehook Extension: s Priority: 1 Application: Set AppData: AUDIOHOOK_INHERIT(Mute)=yes Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] func_audiohookinherit.c: Set audiohook Mute to be inheritable [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'Return' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@add-mutehook:2] Return("SIP/termination1.sd-0000028e", "") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: add-mutehook Extension: s Priority: 2 Application: Return AppData: Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: add-mutehook Extension: s Priority: 2 Application: Return AppData: Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: GOSUB_RETVAL Value: Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: GOSUB_RETVAL Value: Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Result of 'RECORDFILE' is '/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Function result is '55' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Expression result is '1' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@post-originate:4] GotoIf("SIP/termination1.sd-0000028e", "1?record:async-agi-loop,s,1") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 4 Application: GotoIf AppData: 1?record:async-agi-loop,s,1 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 4 Application: GotoIf AppData: 1?record:async-agi-loop,s,1 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Goto (post-originate,s,5) [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Result of 'RECORDFILE' is '/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'Set' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@post-originate:5] Set("SIP/termination1.sd-0000028e", "RECORDFILE=/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 5 Application: Set AppData: RECORDFILE=/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 5 Application: Set AppData: RECORDFILE=/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: RECORDFILE Value: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: RECORDFILE Value: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Result of 'RECORDFILE' is '/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'MixMonitor' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@post-originate:6] MixMonitor("SIP/termination1.sd-0000028e", "/tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul,ba") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 6 Application: MixMonitor AppData: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul,ba Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 6 Application: MixMonitor AppData: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul,ba Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: MIXMONITOR_FILENAME Value: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: MIXMONITOR_FILENAME Value: /tmp/CallRecord/dc815272-aa13-4d84-95a8-5c82a6775b96.ul Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] autochan.c: Created autochan 0x7f644c0c3200 to hold channel SIP/termination1.sd-0000028e (0x7f644c02af38) [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'Goto' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@post-originate:7] Goto("SIP/termination1.sd-0000028e", "async-agi-loop,s,1") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 7 Application: Goto AppData: async-agi-loop,s,1 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: post-originate Extension: s Priority: 7 Application: Goto AppData: async-agi-loop,s,1 Uniqueid: 1414450223.1702 [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Goto (async-agi-loop,s,1) [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'NoOp' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@async-agi-loop:1] NoOp("SIP/termination1.sd-0000028e", "async-agi-loop-s") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: async-agi-loop Extension: s Priority: 1 Application: NoOp AppData: async-agi-loop-s Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: async-agi-loop Extension: s Priority: 1 Application: NoOp AppData: async-agi-loop-s Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Function result is 'Up' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Expression result is '0' [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'GotoIf' [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@async-agi-loop:2] GotoIf("SIP/termination1.sd-0000028e", "0?bye") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: async-agi-loop Extension: s Priority: 2 Application: GotoIf AppData: 0?bye Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: async-agi-loop Extension: s Priority: 2 Application: GotoIf AppData: 0?bye Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Not taking any branch [Oct 27 15:50:24] DEBUG[14374][C-00000381] pbx.c: Launching 'AGI' [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.10E+06, Et=1.81E+08, s/n= 0.01 [Oct 27 15:50:24] VERBOSE[14374][C-00000381] pbx.c: -- Executing [s@async-agi-loop:3] AGI("SIP/termination1.sd-0000028e", "agi:async") in new stack [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: async-agi-loop Extension: s Priority: 3 Application: AGI AppData: agi:async Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Context: async-agi-loop Extension: s Priority: 3 Application: AGI AppData: agi:async Uniqueid: 1414450223.1702 [Oct 27 15:50:24] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: SIP/termination1.sd-0000028e Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Ftermination1.sd-0000028e%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201414450223.1702%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%2047609336033%0Aagi_calleridname%3A%20John%20Fst2%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20async-agi-loop%0Aagi_extension%3A%20s%0Aagi_priority%3A%203%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068284425984%0A%0A [Oct 27 15:50:24] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Start Channel: SIP/termination1.sd-0000028e Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2Ftermination1.sd-0000028e%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201414450223.1702%0Aagi_version%3A%2011.7.0%0Aagi_callerid%3A%2047609336033%0Aagi_calleridname%3A%20John%20Fst2%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20async-agi-loop%0Aagi_extension%3A%20s%0Aagi_priority%3A%203%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140068284425984%0A%0A [Oct 27 15:50:24] VERBOSE[14375][C-00000381] app_mixmonitor.c: == Begin MixMonitor Recording SIP/termination1.sd-0000028e [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.89E+04, Et=1.05E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=5.00E+05, Et=8.48E+07, s/n= 0.01 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.43E+05, Et=8.91E+07, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14374][C-00000381] res_rtp_asterisk.c: 0x7f644c1cb120 -- Probation learning mode pass with source address 10.11.255.1:2222 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=9.84E+04, Et=1.00E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.07E+05, Et=4.78E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.30E+05, Et=9.31E+07, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=2.80E+05, Et=1.03E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.61E+05, Et=3.87E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.95E+05, Et=1.68E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=4.42E+06, Et=2.48E+08, s/n= 0.02 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.08E+05, Et=2.04E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=3.30E+05, Et=2.01E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.05E+05, Et=1.33E+08, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.64E+05, Et=5.70E+07, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.35E+05, Et=4.18E+07, s/n= 0.00 [Oct 27 15:50:24] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.05E+05, Et=8.81E+07, s/n= 0.00 [Oct 27 15:50:25] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.22E+05, Et=2.12E+08, s/n= 0.00 [Oct 27 15:50:25] DEBUG[14370][C-0000037f] dsp.c: tone 1100, Ew=1.54E+05, Et=1.30E+08, s/n= 0.00 [Oct 27 15:50:25] DEBUG[309] manager.c: Running action 'Setvar' [Oct 27 15:50:25] DEBUG[309] manager.c: Running action 'AGI' [Oct 27 15:50:25] VERBOSE[14374][C-00000381] res_agi.c: -- AGI Script Executing Application: (Bridge) Options: (SIP/origination1.sd-0000028d,kK) [Oct 27 15:50:25] VERBOSE[14374][C-00000381] res_musiconhold.c: -- Stopped music on hold on SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Set channel SIP/origination1.sd-0000028d to write format ulaw [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Planning to masquerade channel SIP/origination1.sd-0000028d into the structure of Bridge/SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Done planning to masquerade channel SIP/origination1.sd-0000028d into the structure of Bridge/SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Actually Masquerading SIP/origination1.sd-0000028d(6) into the structure of Bridge/SIP/origination1.sd-0000028d(6) [Oct 27 15:50:25] DEBUG[14374][C-00000381] func_audiohookinherit.c: inheritance fixup occurring for channels Bridge/SIP/origination1.sd-0000028d(0x7f644899b4c8) and SIP/origination1.sd-0000028d(0x7f644c1fe388)[Oct 27 15:50:25] DEBUG[14374][C-00000381] func_audiohookinherit.c: Moved audiohook Mute from Bridge/SIP/origination1.sd-0000028d(0x7f644899b4c8) to SIP/origination1.sd-0000028d(0x7f644c1fe388) [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Putting channel SIP/origination1.sd-0000028d in ulaw/ulaw formats [Oct 27 15:50:25] DEBUG[14374][C-00000381] chan_sip.c: SIP Fixup: New owner for dialogue dbce2dff-c466daf8-620f38cd@10.11.255.6: SIP/origination1.sd-0000028d (Old parent: Bridge/SIP/origination1.sd-0000028d) [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Done Masquerading SIP/origination1.sd-0000028d (6) [Oct 27 15:50:25] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Changing ssrc from 1391501251 to 2061692994 due to a source change [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Set channel SIP/termination1.sd-0000028e to read format ulaw [Oct 27 15:50:25] DEBUG[14374][C-00000381] channel.c: Set channel SIP/termination1.sd-0000028e to write format ulaw [Oct 27 15:50:25] DEBUG[14374][C-00000381] features.c: bridge answer set, chan answer set [Oct 27 15:50:25] DEBUG[14374][C-00000381] features.c: Removing dialed interfaces datastore on SIP/termination1.sd-0000028e since we're bridging [Oct 27 15:50:25] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 27 15:50:25] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Setting the marker bit due to a source update [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: Start Channel: SIP/termination1.sd-0000028e CommandId: 1305920523 Command: EXEC Bridge SIP/origination1.sd-0000028d,kK [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: Context: Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: SIP/origination1.sd-0000028d UniqueID: 1414450217.1697 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Masquerade Privilege: call,all Clone: SIP/origination1.sd-0000028d CloneState: Up Original: Bridge/SIP/origination1.sd-0000028d OriginalState: Up [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/origination1.sd-0000028d Newname: SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Rename Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d Newname: SIP/origination1.sd-0000028d Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/origination1.sd-0000028d Newname: Bridge/SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/origination1.sd-0000028d CallerIDNum: 2132013013 CallerIDName: Alex Uniqueid: 1414450225.1703 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: BridgeExec Privilege: call,all Response: Success Channel1: SIP/termination1.sd-0000028e Channel2: SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/origination1.sd-0000028d Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: SIP/origination1.sd-0000028d Uniqueid: 1414450225.1703 AccountCode: OldAccountCode: [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Bridge Privilege: call,all Bridgestate: Link Bridgetype: core Channel1: SIP/termination1.sd-0000028e Channel2: SIP/origination1.sd-0000028d Uniqueid1: 1414450223.1702 Uniqueid2: 1414450225.1703 CallerID1: 47609336033 CallerID2: 2132013013 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/origination1.sd-0000028d Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: dbce2dff-c466daf8-620f38cd@10.11.255.6 Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/origination1.sd-0000028d Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: dbce2dff-c466daf8-620f38cd@10.11.255.6 Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: Start Channel: SIP/termination1.sd-0000028e CommandId: 1305920523 Command: EXEC Bridge SIP/origination1.sd-0000028d,kK [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: Context: Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: SIP/origination1.sd-0000028d UniqueID: 1414450217.1697 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Masquerade Privilege: call,all Clone: SIP/origination1.sd-0000028d CloneState: Up Original: Bridge/SIP/origination1.sd-0000028d OriginalState: Up [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/origination1.sd-0000028d Newname: SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Rename Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d Newname: SIP/origination1.sd-0000028d Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/origination1.sd-0000028d Newname: Bridge/SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/origination1.sd-0000028d CallerIDNum: 2132013013 CallerIDName: Alex Uniqueid: 1414450225.1703 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: BridgeExec Privilege: call,all Response: Success Channel1: SIP/termination1.sd-0000028e Channel2: SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/origination1.sd-0000028d Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: SIP/origination1.sd-0000028d Uniqueid: 1414450225.1703 AccountCode: OldAccountCode: [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Bridge Privilege: call,all Bridgestate: Link Bridgetype: core Channel1: SIP/termination1.sd-0000028e Channel2: SIP/origination1.sd-0000028d Uniqueid1: 1414450223.1702 Uniqueid2: 1414450225.1703 CallerID1: 47609336033 CallerID2: 2132013013 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/origination1.sd-0000028d Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: dbce2dff-c466daf8-620f38cd@10.11.255.6 Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/origination1.sd-0000028d Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: dbce2dff-c466daf8-620f38cd@10.11.255.6 Uniqueid: 1414450223.1702 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/origination1.sd-0000028d Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:25] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Bridge - SIP/origination1.sd [Oct 27 15:50:25] DEBUG[1319] devicestate.c: Changing state for Bridge/SIP/origination1.sd - state 2 (In use) [Oct 27 15:50:25] DEBUG[1319] devicestate.c: device 'Bridge/SIP/origination1.sd' state '2' [Oct 27 15:50:25] DEBUG[14370][C-0000037f] res_agi.c: No frame read on channel Bridge/SIP/origination1.sd-0000028d, going out ... [Oct 27 15:50:25] DEBUG[14370][C-0000037f] pbx.c: Spawn extension (async-agi-loop-fax,s,3) exited non-zero on 'Bridge/SIP/origination1.sd-0000028d' [Oct 27 15:50:25] VERBOSE[14370][C-0000037f] pbx.c: == Spawn extension (async-agi-loop-fax, s, 3) exited non-zero on 'Bridge/SIP/origination1.sd-0000028d' [Oct 27 15:50:25] DEBUG[14370][C-0000037f] channel.c: Soft-Hanging up channel 'Bridge/SIP/origination1.sd-0000028d' [Oct 27 15:50:25] DEBUG[14370][C-0000037f] channel.c: Set channel Bridge/SIP/origination1.sd-0000028d to read format ulaw [Oct 27 15:50:25] DEBUG[14370][C-0000037f] channel.c: Hanging up channel 'Bridge/SIP/origination1.sd-0000028d' [Oct 27 15:50:25] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for Bridge - SIP/origination1.sd [Oct 27 15:50:25] DEBUG[1319] devicestate.c: Changing state for Bridge/SIP/origination1.sd - state 0 (Unknown) [Oct 27 15:50:25] DEBUG[1319] devicestate.c: device 'Bridge/SIP/origination1.sd' state '0' [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: Bridge/SIP/origination1.sd-0000028d UniqueID: 1414450217.1697 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: End Channel: Bridge/SIP/origination1.sd-0000028d CommandId: 17552001 Command: EXEC MusicOnHold ResultCode: 200 Result: Unknown Result [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Exec Channel: Bridge/SIP/origination1.sd-0000028d CommandID: 1722241529 Result: 200%20result%3D-1%0A [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: End Channel: Bridge/SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Bridge/SIP/origination1.sd-0000028d Variable: AGISTATUS Value: HANGUP Uniqueid: 1414450217.1697 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 Cause: 16 [Oct 27 15:50:25] DEBUG[309] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: Bridge/SIP/origination1.sd-0000028d UniqueID: 1414450217.1697 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: AGIExec Privilege: agi,all SubEvent: End Channel: Bridge/SIP/origination1.sd-0000028d CommandId: 17552001 Command: EXEC MusicOnHold ResultCode: 200 Result: Unknown Result [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: Exec Channel: Bridge/SIP/origination1.sd-0000028d CommandID: 1722241529 Result: 200%20result%3D-1%0A [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: AsyncAGI Privilege: agi,all SubEvent: End Channel: Bridge/SIP/origination1.sd-0000028d [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Bridge/SIP/origination1.sd-0000028d Variable: AGISTATUS Value: HANGUP Uniqueid: 1414450217.1697 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 Cause: 16 [Oct 27 15:50:25] DEBUG[14088] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Bridge/SIP/origination1.sd-0000028d Uniqueid: 1414450217.1697 CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:25] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Oct 27 15:50:25] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Oct 27 15:50:25] DEBUG[309] manager.c: Running action 'Setvar' [Oct 27 15:50:28] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:29] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:30] DEBUG[1325] chan_sip.c: = Looking for Call ID: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 (Checking From) --From tag as326cdbc8 --To-tag [Oct 27 15:50:30] DEBUG[1325] acl.c: For destination '10.11.2.100', our source address is '10.11.2.232'. [Oct 27 15:50:30] DEBUG[1325] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:50:30] DEBUG[1325] netsock2.c: Splitting '10.11.2.100' into... [Oct 27 15:50:30] DEBUG[1325] netsock2.c: ...host '10.11.2.100' and port ''. [Oct 27 15:50:30] DEBUG[1325] chan_sip.c: Allocating new SIP dialog for 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 - INVITE (No RTP) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Found SIP option: -timer- [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Matched SIP option: timer [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 27 15:50:30] DEBUG[1325][C-00000382] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Looking for callid dbce2dff-c466daf8-620f38cd@10.11.255.6 (fromtag E711C95A-94BFEB27 totag as29970a4f) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Matched INCOMING call - their tag is E711C95A-94BFEB27 Our tag is as29970a4f [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: Splitting '10.11.2.100' into... [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: ...host '10.11.2.100' and port ''. [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: Splitting '10.11.2.225' into... [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: ...host '10.11.2.225' and port ''. [Oct 27 15:50:30] DEBUG[1325][C-00000382] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f64482e3ff8' [Oct 27 15:50:30] DEBUG[1325][C-00000382] res_rtp_asterisk.c: Allocated port 16176 for RTP instance '0x7f64482e3ff8' [Oct 27 15:50:30] DEBUG[1325][C-00000382] rtp_engine.c: RTP instance '0x7f64482e3ff8' is setup and ready to go [Oct 27 15:50:30] DEBUG[1325][C-00000382] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f64482e3ff8' [Oct 27 15:50:30] VERBOSE[1325][C-00000382] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Setting NAT on RTP to On [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing session-level SDP o=root 1052929129 1052929129 IN IP4 10.11.2.225... OK. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing session-level SDP s=Asterisk PBX 11.7.0... UNSUPPORTED OR FAILED. [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: Splitting '10.11.2.225' into... [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: ...host '10.11.2.225' and port ''. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing session-level SDP c=IN IP4 10.11.2.225... OK. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 27 15:50:30] DEBUG[1325][C-00000382] rtp_engine.c: Setting payload 0 based on m type on 0x7f64381c9b90 [Oct 27 15:50:30] DEBUG[1325][C-00000382] rtp_engine.c: Setting payload 101 based on m type on 0x7f64381c9b90 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 27 15:50:30] DEBUG[1325][C-00000382] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f64482e3ff8' [Oct 27 15:50:30] DEBUG[1325][C-00000382] rtp_engine.c: Copying payload 0 from 0x7f64381c9b90 to 0x7f64482e41c0 [Oct 27 15:50:30] DEBUG[1325][C-00000382] rtp_engine.c: Copying payload 101 from 0x7f64381c9b90 to 0x7f64482e41c0 [Oct 27 15:50:30] DEBUG[1325][C-00000382] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f64482e3ff8' [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: We're settling with these formats: (ulaw) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Checking SIP call limits for device [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Updating call counter for incoming call [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: Splitting '10.11.2.232:5060' into... [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: ...host '10.11.2.232' and port ''. [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: Splitting '10.11.2.225' into... [Oct 27 15:50:30] DEBUG[1325][C-00000382] netsock2.c: ...host '10.11.2.225' and port ''. [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/sip-transfer-server-0000028f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 8008800004 CallerIDName: John Fst2 AccountCode: Exten: 27609336033 Context: subscriber Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/sip-transfer-server-0000028f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 8008800004 CallerIDName: John Fst2 AccountCode: Exten: 27609336033 Context: subscriber Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: *** Our native formats are (ulaw) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: *** Joint capabilities are (ulaw) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: *** Our capabilities are (ulaw) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: This channel will not be able to handle video. [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: SIPURI Value: sip:8008800004@10.11.2.225:5060 Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: SIPURI Value: sip:8008800004@10.11.2.225:5060 Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: SIPDOMAIN Value: 10.11.2.232 Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: SIPDOMAIN Value: 10.11.2.232 Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: SIPCALLID Value: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: SIPCALLID Value: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/sip-transfer-server-0000028f Uniqueid: 1414450230.1704 Channeltype: SIP SIPcallid: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 SIPfullcontact: [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: ChannelUpdate Privilege: system,all Channel: SIP/sip-transfer-server-0000028f Uniqueid: 1414450230.1704 Channeltype: SIP SIPcallid: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 SIPfullcontact: [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: build_route: Record-Route hop: [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: __PRIREDIRECTREASON Value: UNCONDITIONAL Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: __PRIREDIRECTREASON Value: UNCONDITIONAL Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: __SIPREDIRECTREASON Value: unconditional Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: __SIPREDIRECTREASON Value: unconditional Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: __SIPRDNISDOMAIN Value: localhost Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: __SIPRDNISDOMAIN Value: localhost Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Got redirecting to number 27609336033 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Incoming INVITE with 'timer' option supported [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: INVITE also has "Session-Expires" header. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Session-Expires: 600 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: INVITE also has "Min-SE" header. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Received Min-SE: 180 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Session timer started: 206555 - 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 300000ms [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: SIP transfer: Invite Replace incoming channel should bridge to channel SIP/termination1.sd-0000028e while hanging up channel SIP/origination1.sd-0000028d [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.11.2.100:5060 [Oct 27 15:50:30] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - sip-transfer-server [Oct 27 15:50:30] DEBUG[1319] chan_sip.c: Checking device state for peer sip-transfer-server [Oct 27 15:50:30] DEBUG[1319] devicestate.c: Changing state for SIP/sip-transfer-server - state 1 (Not in use) [Oct 27 15:50:30] DEBUG[1319] devicestate.c: device 'SIP/sip-transfer-server' state '1' [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/sip-transfer-server-0000028f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8008800004 CallerIDName: John Fst2 ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/sip-transfer-server-0000028f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8008800004 CallerIDName: John Fst2 ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Setting framing from config on incoming call [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: ** Our prefcodec: (nothing) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: -- Done with adding codecs to SDP [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.11.2.100:5060 [Oct 27 15:50:30] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - sip-transfer-server [Oct 27 15:50:30] DEBUG[1319] chan_sip.c: Checking device state for peer sip-transfer-server [Oct 27 15:50:30] DEBUG[1319] devicestate.c: Changing state for SIP/sip-transfer-server - state 1 (Not in use) [Oct 27 15:50:30] DEBUG[1319] devicestate.c: device 'SIP/sip-transfer-server' state '1' [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/sip-transfer-server-0000028f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8008800004 CallerIDName: John Fst2 ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/sip-transfer-server-0000028f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8008800004 CallerIDName: John Fst2 ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Invite/Replaces: preparing to masquerade SIP/sip-transfer-server-0000028f into SIP/origination1.sd-0000028d [Oct 27 15:50:30] DEBUG[1325][C-00000382] channel.c: Planning to masquerade channel SIP/sip-transfer-server-0000028f into the structure of SIP/origination1.sd-0000028d [Oct 27 15:50:30] DEBUG[1325][C-00000382] channel.c: Done planning to masquerade channel SIP/sip-transfer-server-0000028f into the structure of SIP/origination1.sd-0000028d [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Invite/Replaces: Going to masquerade SIP/sip-transfer-server-0000028f into SIP/origination1.sd-0000028d [Oct 27 15:50:30] DEBUG[1325][C-00000382] channel.c: Actually Masquerading SIP/sip-transfer-server-0000028f(6) into the structure of SIP/origination1.sd-0000028d(6) [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Masquerade Privilege: call,all Clone: SIP/sip-transfer-server-0000028f CloneState: Up Original: SIP/origination1.sd-0000028d OriginalState: Up [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Masquerade Privilege: call,all Clone: SIP/sip-transfer-server-0000028f CloneState: Up Original: SIP/origination1.sd-0000028d OriginalState: Up [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/sip-transfer-server-0000028f Newname: SIP/sip-transfer-server-0000028f Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/sip-transfer-server-0000028f Newname: SIP/sip-transfer-server-0000028f Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/origination1.sd-0000028d Newname: SIP/sip-transfer-server-0000028f Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/origination1.sd-0000028d Newname: SIP/sip-transfer-server-0000028f Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/sip-transfer-server-0000028f Newname: SIP/origination1.sd-0000028d Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/sip-transfer-server-0000028f Newname: SIP/origination1.sd-0000028d Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/sip-transfer-server-0000028f CallerIDNum: 8008800004 CallerIDName: John Fst2 Uniqueid: 1414450225.1703 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/sip-transfer-server-0000028f CallerIDNum: 8008800004 CallerIDName: John Fst2 Uniqueid: 1414450225.1703 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Oct 27 15:50:30] DEBUG[1325][C-00000382] channel.c: Putting channel SIP/sip-transfer-server-0000028f in ulaw/ulaw formats [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: SIP Fixup: New owner for dialogue 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060: SIP/sip-transfer-server-0000028f (Old parent: SIP/origination1.sd-0000028d) [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: SIP Fixup: New owner for dialogue dbce2dff-c466daf8-620f38cd@10.11.255.6: SIP/origination1.sd-0000028d (Old parent: SIP/sip-transfer-server-0000028f) [Oct 27 15:50:30] DEBUG[1325][C-00000382] channel.c: Done Masquerading SIP/sip-transfer-server-0000028f (6) [Oct 27 15:50:30] DEBUG[1325][C-00000382] res_rtp_asterisk.c: Changing ssrc from 1138438672 to 883198454 due to a source change [Oct 27 15:50:30] DEBUG[1325][C-00000382] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Oct 27 15:50:30] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - origination1.sd [Oct 27 15:50:30] DEBUG[1319] chan_sip.c: Checking device state for peer origination1.sd [Oct 27 15:50:30] DEBUG[1319] devicestate.c: Changing state for SIP/origination1.sd - state 1 (Not in use) [Oct 27 15:50:30] DEBUG[1319] devicestate.c: device 'SIP/origination1.sd' state '1' [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/origination1.sd-0000028d ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: Uniqueid: 1414450230.1704 [Oct 27 15:50:30] DEBUG[1325][C-00000382] channel.c: Hanging up channel 'SIP/origination1.sd-0000028d' [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for dbce2dff-c466daf8-620f38cd@10.11.255.6. [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Session timer stopped: 206547 - dbce2dff-c466daf8-620f38cd@10.11.255.6 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/origination1.sd-0000028d Uniqueid: 1414450230.1704 CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/origination1.sd-0000028d Uniqueid: 1414450230.1704 CallerIDNum: 2132013013 CallerIDName: Alex ConnectedLineNum: ConnectedLineName: AccountCode: Cause: 0 Cause-txt: Unknown [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/sip-transfer-server-0000028f Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/sip-transfer-server-0000028f Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/sip-transfer-server-0000028f Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPEER Value: SIP/sip-transfer-server-0000028f Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/termination1.sd-0000028e Variable: BRIDGEPVTCALLID Value: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 Uniqueid: 1414450223.1702 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPEER Value: SIP/termination1.sd-0000028e Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[309] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[14088] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/sip-transfer-server-0000028f Variable: BRIDGEPVTCALLID Value: 13c820f606c0ef15640ff5e57e27440f@10.11.2.232:5060 Uniqueid: 1414450225.1703 [Oct 27 15:50:30] DEBUG[1319] devicestate.c: No provider found, checking channel drivers for SIP - origination1.sd [Oct 27 15:50:30] DEBUG[1319] chan_sip.c: Checking device state for peer origination1.sd [Oct 27 15:50:30] DEBUG[1319] devicestate.c: Changing state for SIP/origination1.sd - state 1 (Not in use) [Oct 27 15:50:30] DEBUG[1319] devicestate.c: device 'SIP/origination1.sd' state '1' [Oct 27 15:50:30] DEBUG[1325] chan_sip.c: = Looking for Call ID: 634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060 (Checking From) --From tag as326cdbc8 --To-tag as2c268d1b [Oct 27 15:50:30] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Oct 27 15:50:30] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Oct 27 15:50:30] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f64482e3ff8' [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 27 15:50:30] DEBUG[1325][C-00000382] chan_sip.c: Stopping retransmission on '634720f5213c7cfd4bf5e2e5017a1db8@10.11.2.225:5060' of Response 102: Match Found [Oct 27 15:50:30] DEBUG[14374][C-00000381] res_rtp_asterisk.c: 0x7f644830b990 -- Probation learning mode pass with source address 10.11.2.225:14598 [Oct 27 15:50:34] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:35] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:50:38] DEBUG[1325] chan_sip.c: = Looking for Call ID: 3637004963eaa4f9-22068@10.11.2.102 (Checking From) --From tag c9428db5fa22760d6f58389a1f3fceb6-c2c3 --To-tag [Oct 27 15:50:38] DEBUG[1325] acl.c: For destination '10.11.2.102', our source address is '10.11.2.232'. [Oct 27 15:50:38] DEBUG[1325] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:50:38] DEBUG[1325] netsock2.c: Splitting '10.11.2.102' into... [Oct 27 15:50:38] DEBUG[1325] netsock2.c: ...host '10.11.2.102' and port ''. [Oct 27 15:50:38] DEBUG[1325] chan_sip.c: Allocating new SIP dialog for 3637004963eaa4f9-22068@10.11.2.102 - OPTIONS (No RTP) [Oct 27 15:50:38] DEBUG[1325] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Oct 27 15:50:38] DEBUG[1325] netsock2.c: Splitting '10.11.2.232:5060' into... [Oct 27 15:50:38] DEBUG[1325] netsock2.c: ...host '10.11.2.232' and port ''. [Oct 27 15:50:38] DEBUG[1325] netsock2.c: Splitting 'localhost' into... [Oct 27 15:50:38] DEBUG[1325] netsock2.c: ...host 'localhost' and port ''. [Oct 27 15:50:38] DEBUG[1325] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.11.2.102:5060 [Oct 27 15:50:39] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog '3637004963eaa4ea-22068@10.11.2.102' [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: Destroying SIP dialog 3637004963eaa4ea-22068@10.11.2.102 [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '3637004963eaa4ea-22068@10.11.2.102' [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: 001. Rx OPTIONS / 10 OPTIONS / sip:10.11.2.232:5060 [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: 002. TxResp SIP/2.0 / 10 OPTIONS - 200 OK [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: 003. SchedDestroy 32000 ms [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: 004. AutoDestroy 3637004963eaa4ea-22068@10.11.2.102 [Oct 27 15:50:40] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '3637004963eaa4ea-22068@10.11.2.102' [Oct 27 15:50:40] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:50:44] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:45] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:50:49] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:50] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:50:54] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:50:55] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:50:59] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:00] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:02] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog 'dbce2dff-c466daf8-620f38cd@10.11.255.6' [Oct 27 15:51:04] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:05] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:08] DEBUG[1325] chan_sip.c: = Looking for Call ID: 3637004963eaa508-22068@10.11.2.102 (Checking From) --From tag c9428db5fa22760d6f58389a1f3fceb6-4b0b --To-tag [Oct 27 15:51:08] DEBUG[1325] acl.c: For destination '10.11.2.102', our source address is '10.11.2.232'. [Oct 27 15:51:08] DEBUG[1325] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:51:08] DEBUG[1325] netsock2.c: Splitting '10.11.2.102' into... [Oct 27 15:51:08] DEBUG[1325] netsock2.c: ...host '10.11.2.102' and port ''. [Oct 27 15:51:08] DEBUG[1325] chan_sip.c: Allocating new SIP dialog for 3637004963eaa508-22068@10.11.2.102 - OPTIONS (No RTP) [Oct 27 15:51:08] DEBUG[1325] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Oct 27 15:51:08] DEBUG[1325] netsock2.c: Splitting '10.11.2.232:5060' into... [Oct 27 15:51:08] DEBUG[1325] netsock2.c: ...host '10.11.2.232' and port ''. [Oct 27 15:51:08] DEBUG[1325] netsock2.c: Splitting 'localhost' into... [Oct 27 15:51:08] DEBUG[1325] netsock2.c: ...host 'localhost' and port ''. [Oct 27 15:51:08] DEBUG[1325] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.11.2.102:5060 [Oct 27 15:51:09] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog '3637004963eaa4f9-22068@10.11.2.102' [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: Destroying SIP dialog 3637004963eaa4f9-22068@10.11.2.102 [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '3637004963eaa4f9-22068@10.11.2.102' [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: 001. Rx OPTIONS / 10 OPTIONS / sip:10.11.2.232:5060 [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: 002. TxResp SIP/2.0 / 10 OPTIONS - 200 OK [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: 003. SchedDestroy 32000 ms [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: 004. AutoDestroy 3637004963eaa4f9-22068@10.11.2.102 [Oct 27 15:51:10] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '3637004963eaa4f9-22068@10.11.2.102' [Oct 27 15:51:10] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:14] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:15] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:19] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:20] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:24] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:25] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:29] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:30] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:34] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:35] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:38] DEBUG[1325] chan_sip.c: = Looking for Call ID: 3637004963eaa517-22068@10.11.2.102 (Checking From) --From tag c9428db5fa22760d6f58389a1f3fceb6-2253 --To-tag [Oct 27 15:51:38] DEBUG[1325] acl.c: For destination '10.11.2.102', our source address is '10.11.2.232'. [Oct 27 15:51:38] DEBUG[1325] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.11.2.232:5060 [Oct 27 15:51:38] DEBUG[1325] netsock2.c: Splitting '10.11.2.102' into... [Oct 27 15:51:38] DEBUG[1325] netsock2.c: ...host '10.11.2.102' and port ''. [Oct 27 15:51:38] DEBUG[1325] chan_sip.c: Allocating new SIP dialog for 3637004963eaa517-22068@10.11.2.102 - OPTIONS (No RTP) [Oct 27 15:51:38] DEBUG[1325] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Oct 27 15:51:38] DEBUG[1325] netsock2.c: Splitting '10.11.2.232:5060' into... [Oct 27 15:51:38] DEBUG[1325] netsock2.c: ...host '10.11.2.232' and port ''. [Oct 27 15:51:38] DEBUG[1325] netsock2.c: Splitting 'localhost' into... [Oct 27 15:51:38] DEBUG[1325] netsock2.c: ...host 'localhost' and port ''. [Oct 27 15:51:38] DEBUG[1325] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.11.2.102:5060 [Oct 27 15:51:39] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: Auto destroying SIP dialog '3637004963eaa508-22068@10.11.2.102' [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: Destroying SIP dialog 3637004963eaa508-22068@10.11.2.102 [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: ---------- SIP HISTORY for '3637004963eaa508-22068@10.11.2.102' [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: * SIP Call [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: 001. Rx OPTIONS / 10 OPTIONS / sip:10.11.2.232:5060 [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: 002. TxResp SIP/2.0 / 10 OPTIONS - 200 OK [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: 003. SchedDestroy 32000 ms [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: 004. AutoDestroy 3637004963eaa508-22068@10.11.2.102 [Oct 27 15:51:40] DEBUG[1325] chan_sip.c: ---------- END SIP HISTORY for '3637004963eaa508-22068@10.11.2.102' [Oct 27 15:51:40] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:44] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:45] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 27 15:51:49] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Oct 27 15:51:50] DEBUG[14374][C-00000381] res_rtp_asterisk.c: Got RTCP report of 64 bytes