[Jun 5 11:45:26] VERBOSE[5604] config.c: == Parsing '/etc/asterisk/logger.conf': [Jun 5 11:45:26] DEBUG[5604] config.c: Parsing /etc/asterisk/logger.conf [Jun 5 11:45:26] VERBOSE[5604] config.c: == Found [Jun 5 11:45:26] VERBOSE[5604] logger.c: Asterisk Queue Logger restarted [Jun 5 11:45:26] VERBOSE[5604] asterisk.c: -- Remote UNIX connection disconnected [Jun 5 11:45:27] DEBUG[5332] sig_wat.c: Span 1:Signal strength:(-53)dBm (BER:less than 0.2%) [Jun 5 11:45:28] DEBUG[5589] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jun 5 11:45:28] DEBUG[5589] res_rtp_asterisk.c: Got RTCP report of 96 bytes [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.1.179:11795 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 16777216 FractionLost: 0 PacketsLost: 1 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 159 LastSR: 46629.820315898672840704 DLSR: 2.5781(sec) RTT: 116(sec) [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.1.179:11795 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 16777216 FractionLost: 0 PacketsLost: 1 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 159 LastSR: 46629.820315898672840704 DLSR: 2.5781(sec) RTT: 116(sec) [Jun 5 11:45:28] DEBUG[5353] manager.c: Running action 'Command' [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: <--- SIP read from UDP:192.168.1.84:5060 ---> INVITE sip:8000@192.168.1.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKjuunttrm Max-Forwards: 70 To: From: "EHCP" ;tag=jxabg Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 155 INVITE Contact: Content-Type: application/sdp Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE Supported: replaces,norefersub,100rel User-Agent: Twinkle/1.4.2 Content-Length: 308 v=0 o=twinkle 977512427 846977547 IN IP4 192.168.1.84 s=- c=IN IP4 192.168.1.84 t=0 0 m=audio 11000 RTP/AVP 98 97 8 0 3 101 a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 <-------------> [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 0 [ 36]: INVITE sip:8000@192.168.1.66 SIP/2.0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKjuunttrm [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 3 [ 27]: To: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 4 [ 45]: From: "EHCP" ;tag=jxabg [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 5 [ 44]: Call-ID: qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 6 [ 16]: CSeq: 155 INVITE [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 7 [ 31]: Contact: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 8 [ 29]: Content-Type: application/sdp [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 9 [ 78]: Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 10 [ 37]: Supported: replaces,norefersub,100rel [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 11 [ 25]: User-Agent: Twinkle/1.4.2 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 12 [ 19]: Content-Length: 308 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 13 [ 0]: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 0 [ 3]: v=0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 1 [ 49]: o=twinkle 977512427 846977547 IN IP4 192.168.1.84 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 2 [ 3]: s=- [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.1.84 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 5 [ 37]: m=audio 11000 RTP/AVP 98 97 8 0 3 101 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 6 [ 23]: a=rtpmap:98 speex/16000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 7 [ 22]: a=rtpmap:97 speex/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 9 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 10 [ 19]: a=rtpmap:3 GSM/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 12 [ 15]: a=fmtp:101 0-15 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 13 [ 10]: a=ptime:20 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: --- (13 headers 14 lines) --- [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: = Looking for Call ID: qozpzhlflfddxya@eabad.palosanto.com (Checking From) --From tag jxabg --To-tag [Jun 5 11:45:28] DEBUG[5331] acl.c: For destination '192.168.1.84', our source address is '192.168.1.66'. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.66:5060 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Allocating new SIP dialog for qozpzhlflfddxya@eabad.palosanto.com - INVITE (No RTP) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces,norefersub,100rel" [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Found SIP option: -replaces- [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Matched SIP option: replaces [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Found SIP option: -norefersub- [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Matched SIP option: norefersub [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Found SIP option: -100rel- [Jun 5 11:45:28] DEBUG[5331] sip/reqresp_parser.c: Matched SIP option: 100rel [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.84' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.84' and port ''. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Sending to 192.168.1.84:5060 (NAT) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Initializing initreq for method INVITE - callid qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Using INVITE request as basis request - qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found peer '290' for '290' from 192.168.1.84:5060 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.1.84:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.84;branch=z9hG4bKjuunttrm;received=192.168.1.84;rport=5060 From: "EHCP" ;tag=jxabg To: ;tag=as334dd61b Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 155 INVITE Server: FPBX-2.8.1(1.8.13.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6aa31c9e" Content-Length: 0 <------------> [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #490 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.84:5060 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Scheduling destruction of SIP dialog 'qozpzhlflfddxya@eabad.palosanto.com' in 6400 ms (Method: INVITE) [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: <--- SIP read from UDP:192.168.1.84:5060 ---> ACK sip:8000@192.168.1.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKjuunttrm Max-Forwards: 70 To: ;tag=as334dd61b From: "EHCP" ;tag=jxabg Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 155 ACK User-Agent: Twinkle/1.4.2 Content-Length: 0 <-------------> [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 0 [ 33]: ACK sip:8000@192.168.1.66 SIP/2.0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKjuunttrm [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 3 [ 42]: To: ;tag=as334dd61b [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 4 [ 45]: From: "EHCP" ;tag=jxabg [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 5 [ 44]: Call-ID: qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 6 [ 13]: CSeq: 155 ACK [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 7 [ 25]: User-Agent: Twinkle/1.4.2 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: --- (9 headers 0 lines) --- [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: = Looking for Call ID: qozpzhlflfddxya@eabad.palosanto.com (Checking From) --From tag jxabg --To-tag as334dd61b [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #490 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Stopping retransmission on 'qozpzhlflfddxya@eabad.palosanto.com' of Response 155: Match Found [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: <--- SIP read from UDP:192.168.1.84:5060 ---> INVITE sip:8000@192.168.1.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKimfnkgnt Max-Forwards: 70 To: From: "EHCP" ;tag=jxabg Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 156 INVITE Contact: Content-Type: application/sdp Authorization: Digest username="290",realm="asterisk",nonce="6aa31c9e",uri="sip:8000@192.168.1.66",response="d663651596a90d5d18b58bfe3b0260fc",algorithm=MD5 Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE Supported: replaces,norefersub,100rel User-Agent: Twinkle/1.4.2 Content-Length: 308 v=0 o=twinkle 977512427 846977547 IN IP4 192.168.1.84 s=- c=IN IP4 192.168.1.84 t=0 0 m=audio 11000 RTP/AVP 98 97 8 0 3 101 a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 <-------------> [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 0 [ 36]: INVITE sip:8000@192.168.1.66 SIP/2.0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKimfnkgnt [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 3 [ 27]: To: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 4 [ 45]: From: "EHCP" ;tag=jxabg [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 5 [ 44]: Call-ID: qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 6 [ 16]: CSeq: 156 INVITE [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 7 [ 31]: Contact: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 8 [ 29]: Content-Type: application/sdp [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 9 [156]: Authorization: Digest username="290",realm="asterisk",nonce="6aa31c9e",uri="sip:8000@192.168.1.66",response="d663651596a90d5d18b58bfe3b0260fc",algorithm=MD5 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 10 [ 78]: Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 11 [ 37]: Supported: replaces,norefersub,100rel [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 12 [ 25]: User-Agent: Twinkle/1.4.2 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 13 [ 19]: Content-Length: 308 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 14 [ 0]: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 0 [ 3]: v=0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 1 [ 49]: o=twinkle 977512427 846977547 IN IP4 192.168.1.84 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 2 [ 3]: s=- [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.1.84 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 5 [ 37]: m=audio 11000 RTP/AVP 98 97 8 0 3 101 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 6 [ 23]: a=rtpmap:98 speex/16000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 7 [ 22]: a=rtpmap:97 speex/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 9 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 10 [ 19]: a=rtpmap:3 GSM/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 12 [ 15]: a=fmtp:101 0-15 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Body 13 [ 10]: a=ptime:20 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: --- (14 headers 14 lines) --- [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: = Looking for Call ID: qozpzhlflfddxya@eabad.palosanto.com (Checking From) --From tag jxabg --To-tag [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.84' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.84' and port ''. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Sending to 192.168.1.84:5060 (NAT) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Initializing initreq for method INVITE - callid qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Using INVITE request as basis request - qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found peer '290' for '290' from 192.168.1.84:5060 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x18da4268' [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Allocated port 14908 for RTP instance '0x18da4268' [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: RTP instance '0x18da4268' is setup and ready to go [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x18da55f8' [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Allocated port 17646 for RTP instance '0x18da55f8' [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: RTP instance '0x18da55f8' is setup and ready to go [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x18da55f8' [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x18da4268' [Jun 5 11:45:28] VERBOSE[5331] netsock2.c: == Using SIP RTP TOS bits 184 [Jun 5 11:45:28] VERBOSE[5331] netsock2.c: == Using SIP RTP CoS mark 5 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Setting NAT on RTP to On [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Setting NAT on VRTP to On [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing session-level SDP o=twinkle 977512427 846977547 IN IP4 192.168.1.84... UNSUPPORTED. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.84' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.84' and port ''. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.84... OK. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found RTP audio format 98 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Setting payload 98 based on m type on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found RTP audio format 97 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Setting payload 97 based on m type on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found RTP audio format 8 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Setting payload 8 based on m type on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found RTP audio format 0 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Setting payload 0 based on m type on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found RTP audio format 3 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Setting payload 3 based on m type on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found RTP audio format 101 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Setting payload 101 based on m type on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found audio description format speex for ID 98 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 speex/16000... OK. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found audio description format speex for ID 97 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 speex/8000... OK. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found audio description format PCMA for ID 8 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found audio description format PCMU for ID 0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found audio description format GSM for ID 3 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Incorporating payload 0 on 0x40e6f880 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Incorporating payload 3 on 0x40e6f880 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Incorporating payload 8 on 0x40e6f880 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Incorporating payload 97 on 0x40e6f880 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Incorporating payload 98 on 0x40e6f880 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Incorporating payload 101 on 0x40e6f880 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Capabilities: us - 0x3c000e (gsm|ulaw|alaw|h261|h263|h263p|h264), peer - audio=0x20000020e (gsm|ulaw|alaw|speex|speex16)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x18da4268' [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Peer audio RTP is at port 192.168.1.84:11000 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Copying payload 0 from 0x40e6f880 to 0x18da4430 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Copying payload 3 from 0x40e6f880 to 0x18da4430 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Copying payload 8 from 0x40e6f880 to 0x18da4430 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Copying payload 97 from 0x40e6f880 to 0x18da4430 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Copying payload 98 from 0x40e6f880 to 0x18da4430 [Jun 5 11:45:28] DEBUG[5331] rtp_engine.c: Copying payload 101 from 0x40e6f880 to 0x18da4430 [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x18da4268' [Jun 5 11:45:28] DEBUG[5331] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x18da55f8' [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Peer doesn't provide video [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Checking SIP call limits for device 290 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Updating call counter for incoming call [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Call from peer '290' is 1 out of 2147483647 [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:28] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:28] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: Looking for 8000 in from-internal (domain 192.168.1.66) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: *** Our capabilities are 0x3c000e (gsm|ulaw|alaw|h261|h263|h263p|h264) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: build_route: Contact hop: [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: list_route: hop: [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: SIP/290-0000000b: New call is still down.... Trying... [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: <--- Transmitting (NAT) to 192.168.1.84:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.84;branch=z9hG4bKimfnkgnt;received=192.168.1.84;rport=5060 From: "EHCP" ;tag=jxabg To: Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 156 INVITE Server: FPBX-2.8.1(1.8.13.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.84:5060 [Jun 5 11:45:28] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for SIP - 290 [Jun 5 11:45:28] DEBUG[5309] chan_sip.c: Checking device state for peer 290 [Jun 5 11:45:28] DEBUG[5309] devicestate.c: Changing state for SIP/290 - state 2 (In use) [Jun 5 11:45:28] DEBUG[5309] devicestate.c: device 'SIP/290' state '2' [Jun 5 11:45:28] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for SIP - 290 [Jun 5 11:45:28] DEBUG[5309] chan_sip.c: Checking device state for peer 290 [Jun 5 11:45:28] DEBUG[5309] devicestate.c: Changing state for SIP/290 - state 2 (In use) [Jun 5 11:45:28] DEBUG[5309] devicestate.c: device 'SIP/290' state '2' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/290-0000000b ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 290 CallerIDName: device AccountCode: Exten: 8000 Context: from-internal Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SIPURI Value: sip:290@192.168.1.84 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SIPDOMAIN Value: 192.168.1.66 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SIPCALLID Value: qozpzhlflfddxya@eabad.palosanto.com Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/290-0000000b ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 290 CallerIDName: device ConnectedLineNum: ConnectedLineName: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/290-0000000b ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 290 CallerIDName: device AccountCode: Exten: 8000 Context: from-internal Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SIPURI Value: sip:290@192.168.1.84 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SIPDOMAIN Value: 192.168.1.66 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SIPCALLID Value: qozpzhlflfddxya@eabad.palosanto.com Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/290-0000000b ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 290 CallerIDName: device ConnectedLineNum: ConnectedLineName: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5310] app_queue.c: Extension '290@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 5 11:45:28] DEBUG[5351] app_queue.c: Device 'SIP/290' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 5 11:45:28] DEBUG[5351] app_queue.c: Device 'SIP/290' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 290 Context: ext-local Hint: SIP/290 Status: 1 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 290 Context: ext-local Hint: SIP/290 Status: 1 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Macro' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:1] Macro("SIP/290-0000000b", "user-callerid,") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 1 Application: Macro AppData: user-callerid, Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 1 Application: Macro AppData: user-callerid, Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_EXTEN Value: 8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_EXTEN Value: 8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: ARG1 Value: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: ARG1 Value: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is NULL [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is NULL [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/290-0000000b", "AMPUSER=290") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 1 Application: Set AppData: AMPUSER=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSER Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'CHANNEL' is 'SIP/290-0000000b' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/290-0000000b", "0?report") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 2 Application: GotoIf AppData: 0?report Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Not taking any branch [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'REALCALLERIDNUM' is NULL [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'ExecIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/290-0000000b", "1?Set(REALCALLERIDNUM=290)") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 3 Application: ExecIf AppData: 1?Set(REALCALLERIDNUM=290) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: REALCALLERIDNUM Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: ExecIf [Jun 5 11:45:28] DEBUG[5605] pbx.c: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'REALCALLERIDNUM' is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'REALCALLERIDNUM' is '290' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/290-0000000b", "AMPUSER=290") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 4 Application: Set AppData: AMPUSER=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSER Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is 'ZoIPer' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/290-0000000b", "AMPUSERCIDNAME=ZoIPer") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 5 Application: Set AppData: AMPUSERCIDNAME=ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSERCIDNAME Value: ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSERCIDNAME' is 'ZoIPer' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/290-0000000b", "0?report") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 6 Application: GotoIf AppData: 0?report Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Not taking any branch [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'DB_RESULT' is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/290-0000000b", "AMPUSERCID=290") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 7 Application: Set AppData: AMPUSERCID=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSERCID Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSERCIDNAME' is 'ZoIPer' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSERCID' is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/290-0000000b", "CALLERID(all)="ZoIPer" <290>") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 8 Application: Set AppData: CALLERID(all)="ZoIPer" <290> Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5605] db.c: Unable to find key '290/language' in family 'AMPUSER' [Jun 5 11:45:28] DEBUG[5605] func_db.c: DB: AMPUSER/290/language not found in database. [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5605] db.c: Unable to find key '290/language' in family 'AMPUSER' [Jun 5 11:45:28] DEBUG[5605] func_db.c: DB: AMPUSER/290/language not found in database. [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'ExecIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/290-0000000b", "0?Set(CHANNEL(language)=)") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 9 Application: ExecIf AppData: 0?Set(CHANNEL(language)=) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: ExecIf [Jun 5 11:45:28] DEBUG[5605] pbx.c: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)}" != ""' len 31) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5605] db.c: Unable to find key '290/language' in family 'AMPUSER' [Jun 5 11:45:28] DEBUG[5605] func_db.c: DB: AMPUSER/290/language not found in database. [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)})' len 31) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'AMPUSER' is '290' [Jun 5 11:45:28] DEBUG[5605] db.c: Unable to find key '290/language' in family 'AMPUSER' [Jun 5 11:45:28] DEBUG[5605] func_db.c: DB: AMPUSER/290/language not found in database. [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'ARG1' is '' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/290-0000000b", "0?continue") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 10 Application: GotoIf AppData: 0?continue Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Not taking any branch [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'TTL' is NULL [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'TTL' is NULL [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '-1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '64' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/290-0000000b", "__TTL=64") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 11 Application: Set AppData: __TTL=64 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __TTL Value: 64 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'TTL' is '64' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/290-0000000b", "1?continue") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 12 Application: GotoIf AppData: 1?continue Uniqueid: 1338914728.15 [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Goto (macro-user-callerid,s,19) [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:19] Set("SIP/290-0000000b", "CALLERID(number)=290") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 19 Application: Set AppData: CALLERID(number)=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is 'ZoIPer' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:20] Set("SIP/290-0000000b", "CALLERID(name)=ZoIPer") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 20 Application: Set AppData: CALLERID(name)=ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Set [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '"ZoIPer" <290>' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [s@macro-user-callerid:21] NoOp("SIP/290-0000000b", "Using CallerID "ZoIPer" <290>") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 21 Application: NoOp AppData: Using CallerID "ZoIPer" <290> Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 0 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Answer' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:2] Answer("SIP/290-0000000b", "") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 2 Application: Answer AppData: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for SIP - 290 [Jun 5 11:45:28] DEBUG[5309] chan_sip.c: Checking device state for peer 290 [Jun 5 11:45:28] DEBUG[5309] devicestate.c: Changing state for SIP/290 - state 2 (In use) [Jun 5 11:45:28] DEBUG[5309] devicestate.c: device 'SIP/290' state '2' [Jun 5 11:45:28] DEBUG[5351] app_queue.c: Device 'SIP/290' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/290-0000000b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 290 CallerIDName: ZoIPer ConnectedLineNum: ConnectedLineName: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: SIP answering channel: SIP/290-0000000b [Jun 5 11:45:28] DEBUG[5605] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: Setting framing from config on incoming call [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True Text flag: True [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 5 11:45:28] VERBOSE[5605] chan_sip.c: Audio is at 14908 [Jun 5 11:45:28] VERBOSE[5605] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jun 5 11:45:28] VERBOSE[5605] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jun 5 11:45:28] VERBOSE[5605] chan_sip.c: Adding codec 0x2 (gsm) to SDP [Jun 5 11:45:28] VERBOSE[5605] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: -- Done with adding codecs to SDP [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Jun 5 11:45:28] VERBOSE[5605] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.1.84:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.84;branch=z9hG4bKimfnkgnt;received=192.168.1.84;rport=5060 From: "EHCP" ;tag=jxabg To: ;tag=as2cc37702 Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 156 INVITE Server: FPBX-2.8.1(1.8.13.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 282 v=0 o=root 120773395 120773395 IN IP4 192.168.1.66 s=Asterisk PBX 1.8.13.0 c=IN IP4 192.168.1.66 t=0 0 m=audio 14908 RTP/AVP 0 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #493 [Jun 5 11:45:28] DEBUG[5605] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.84:5060 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 1 Application: Set AppData: AMPUSER=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSER Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 2 Application: GotoIf AppData: 0?report Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 3 Application: ExecIf AppData: 1?Set(REALCALLERIDNUM=290) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: REALCALLERIDNUM Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 4 Application: Set AppData: AMPUSER=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSER Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 5 Application: Set AppData: AMPUSERCIDNAME=ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSERCIDNAME Value: ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 6 Application: GotoIf AppData: 0?report Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 7 Application: Set AppData: AMPUSERCID=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: AMPUSERCID Value: 290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 8 Application: Set AppData: CALLERID(all)="ZoIPer" <290> Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 9 Application: ExecIf AppData: 0?Set(CHANNEL(language)=) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 10 Application: GotoIf AppData: 0?continue Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 11 Application: Set AppData: __TTL=64 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __TTL Value: 64 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 12 Application: GotoIf AppData: 1?continue Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 19 Application: Set AppData: CALLERID(number)=290 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 20 Application: Set AppData: CALLERID(name)=ZoIPer Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-user-callerid Extension: s Priority: 21 Application: NoOp AppData: Using CallerID "ZoIPer" <290> Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 0 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 2 Application: Answer AppData: Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/290-0000000b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 290 CallerIDName: ZoIPer ConnectedLineNum: ConnectedLineName: Uniqueid: 1338914728.15 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: <--- SIP read from UDP:192.168.1.84:5060 ---> ACK sip:8000@192.168.1.66:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKfnwngfhc Max-Forwards: 70 To: ;tag=as2cc37702 From: "EHCP" ;tag=jxabg Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 156 ACK Authorization: Digest username="290",realm="asterisk",nonce="6aa31c9e",uri="sip:8000@192.168.1.66",response="d663651596a90d5d18b58bfe3b0260fc",algorithm=MD5 User-Agent: Twinkle/1.4.2 Content-Length: 0 <-------------> [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 0 [ 38]: ACK sip:8000@192.168.1.66:5060 SIP/2.0 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKfnwngfhc [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 3 [ 42]: To: ;tag=as2cc37702 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 4 [ 45]: From: "EHCP" ;tag=jxabg [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 5 [ 44]: Call-ID: qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 6 [ 13]: CSeq: 156 ACK [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 7 [156]: Authorization: Digest username="290",realm="asterisk",nonce="6aa31c9e",uri="sip:8000@192.168.1.66",response="d663651596a90d5d18b58bfe3b0260fc",algorithm=MD5 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 8 [ 25]: User-Agent: Twinkle/1.4.2 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 5 11:45:28] VERBOSE[5331] chan_sip.c: --- (10 headers 0 lines) --- [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: = Looking for Call ID: qozpzhlflfddxya@eabad.palosanto.com (Checking From) --From tag jxabg --To-tag as2cc37702 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #493 [Jun 5 11:45:28] DEBUG[5331] chan_sip.c: Stopping retransmission on 'qozpzhlflfddxya@eabad.palosanto.com' of Response 156: Match Found [Jun 5 11:45:28] DEBUG[5605] res_rtp_asterisk.c: Got RTCP report of 44 bytes [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'EXTEN' is '8000' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'CHANNEL' is 'SIP/290-0000000b' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:3] Set("SIP/290-0000000b", "__BLKVM_OVERRIDE=BLKVM/8000/SIP/290-0000000b") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 3 Application: Set AppData: __BLKVM_OVERRIDE=BLKVM/8000/SIP/290-0000000b Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 3 Application: Set AppData: __BLKVM_OVERRIDE=BLKVM/8000/SIP/290-0000000b Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __BLKVM_OVERRIDE Value: BLKVM/8000/SIP/290-0000000b Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __BLKVM_OVERRIDE Value: BLKVM/8000/SIP/290-0000000b Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'EXTEN' is '8000' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:4] Set("SIP/290-0000000b", "__BLKVM_BASE=8000") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 4 Application: Set AppData: __BLKVM_BASE=8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 4 Application: Set AppData: __BLKVM_BASE=8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __BLKVM_BASE Value: 8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __BLKVM_BASE Value: 8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'BLKVM_OVERRIDE' is 'BLKVM/8000/SIP/290-0000000b' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:5] Set("SIP/290-0000000b", "DB(BLKVM/8000/SIP/290-0000000b)=TRUE") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 5 Application: Set AppData: DB(BLKVM/8000/SIP/290-0000000b)=TRUE Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 5 Application: Set AppData: DB(BLKVM/8000/SIP/290-0000000b)=TRUE Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'DIAL_OPTIONS' is 'tr' [Jun 5 11:45:28] DEBUG[5605] func_strings.c: FUNCTION REGEX ((M[(]auto-blkvm[)]))(tr) [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '0' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'DIAL_OPTIONS' is 'tr' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'ExecIf' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:6] ExecIf("SIP/290-0000000b", "1?Set(_DIAL_OPTIONS=trM(auto-blkvm))") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 6 Application: ExecIf AppData: 1?Set(_DIAL_OPTIONS=trM(auto-blkvm)) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 6 Application: ExecIf AppData: 1?Set(_DIAL_OPTIONS=trM(auto-blkvm)) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: _DIAL_OPTIONS Value: trM(auto-blkvm) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: _DIAL_OPTIONS Value: trM(auto-blkvm) Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'EXTEN' is '8000' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:7] Set("SIP/290-0000000b", "__NODEST=8000") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 7 Application: Set AppData: __NODEST=8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 7 Application: Set AppData: __NODEST=8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __NODEST Value: 8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: __NODEST Value: 8000 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'EXTEN' is '8000' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'EPOCH' is '1338914728' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Function result is '20120605-114528' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Result of 'UNIQUEID' is '1338914728.15' [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Set' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:8] Set("SIP/290-0000000b", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 8 Application: Set AppData: MONITOR_FILENAME=/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 8 Application: Set AppData: MONITOR_FILENAME=/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MONITOR_FILENAME Value: /var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MONITOR_FILENAME Value: /var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] pbx.c: Launching 'Queue' [Jun 5 11:45:28] VERBOSE[5605] pbx.c: -- Executing [8000@from-internal:9] Queue("SIP/290-0000000b", "8000,t,,") in new stack [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 9 Application: Queue AppData: 8000,t,, Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: 8000 Priority: 9 Application: Queue AppData: 8000,t,, Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_queue.c: NO QUEUE_PRIO variable found. Using default. [Jun 5 11:45:28] DEBUG[5605] app_queue.c: queue: 8000, options: t, url: , announce: , expires: 0, priority: 0 [Jun 5 11:45:28] DEBUG[5605] app_queue.c: Queue 8000 has no realtime members defined. No need for update [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Join Privilege: call,all Channel: SIP/290-0000000b CallerIDNum: 290 CallerIDName: ZoIPer ConnectedLineNum: unknown ConnectedLineName: unknown Queue: 8000 Position: 1 Count: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Join Privilege: call,all Channel: SIP/290-0000000b CallerIDNum: 290 CallerIDName: ZoIPer ConnectedLineNum: unknown ConnectedLineName: unknown Queue: 8000 Position: 1 Count: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:28] DEBUG[5605] app_queue.c: Queue '8000' Join, Channel 'SIP/290-0000000b', Position '1' [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Start Channel: SIP/290-0000000b UniqueID: 1338914728.15 Class: default [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Start Channel: SIP/290-0000000b UniqueID: 1338914728.15 Class: default [Jun 5 11:45:28] VERBOSE[5605] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/290-0000000b [Jun 5 11:45:28] DEBUG[5605] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:28] DEBUG[5605] app_queue.c: There is 1 available member. [Jun 5 11:45:28] DEBUG[5605] app_queue.c: It's our turn (SIP/290-0000000b). [Jun 5 11:45:28] DEBUG[5605] app_queue.c: SIP/290-0000000b is trying to call a queue member. [Jun 5 11:45:28] DEBUG[5605] app_queue.c: (Parallel) Trying 'Agent/101' with metric 0 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Agent/101 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: 7888 Context: from-internal Uniqueid: 1338914728.16 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: Agent/101 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: 7888 Context: from-internal Uniqueid: 1338914728.16 [Jun 5 11:45:28] DEBUG[5589] chan_agent.c: agent_cont_sleep() returning 0 [Jun 5 11:45:28] DEBUG[5605] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 5 11:45:28] VERBOSE[5605] res_musiconhold.c: -- Stopped music on hold on SIP/300-0000000a [Jun 5 11:45:28] DEBUG[5605] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:28] DEBUG[5605] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: SIP/300-0000000a UniqueID: 1338914625.14 [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: SIP/300-0000000a UniqueID: 1338914625.14 [Jun 5 11:45:28] DEBUG[5353] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: Agent/101 CallerIDNum: 8000 CallerIDName: Uniqueid: 1338914728.16 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Jun 5 11:45:28] DEBUG[5387] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: Agent/101 CallerIDNum: 8000 CallerIDName: Uniqueid: 1338914728.16 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable MONITOR_FILENAME. [Jun 5 11:45:28] DEBUG[5605] channel.c: Copying hard-transferable variable NODEST. [Jun 5 11:45:28] DEBUG[5605] channel.c: Copying soft-transferable variable DIAL_OPTIONS. [Jun 5 11:45:28] DEBUG[5605] channel.c: Copying hard-transferable variable BLKVM_BASE. [Jun 5 11:45:28] DEBUG[5605] channel.c: Copying hard-transferable variable BLKVM_OVERRIDE. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable MACRO_DEPTH. [Jun 5 11:45:28] DEBUG[5605] channel.c: Copying hard-transferable variable TTL. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable AMPUSERCID. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable DB_RESULT. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable AMPUSERCIDNAME. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable AMPUSER. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable REALCALLERIDNUM. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable SIPCALLID. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable SIPDOMAIN. [Jun 5 11:45:28] DEBUG[5605] channel.c: Not copying variable SIPURI. [Jun 5 11:45:28] VERBOSE[5605] chan_agent.c: -- agent_call, call to agent '101' call on 'SIP/300-0000000a' [Jun 5 11:45:28] DEBUG[5605] chan_agent.c: Playing beep, lang 'en' [Jun 5 11:45:28] DEBUG[5605] channel.c: Set channel SIP/300-0000000a to write format gsm [Jun 5 11:45:28] DEBUG[5605] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:28] VERBOSE[5605] file.c: -- Playing 'beep.gsm' (language 'en') [Jun 5 11:45:28] DEBUG[5605] chan_agent.c: Played beep, result '0' [Jun 5 11:45:29] DEBUG[5605] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:29] DEBUG[5605] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:29] DEBUG[5605] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:29] DEBUG[5605] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:29] DEBUG[5605] chan_agent.c: Waited for stream, result '0' [Jun 5 11:45:29] DEBUG[5605] chan_agent.c: Set read format, result '0' [Jun 5 11:45:29] DEBUG[5605] chan_agent.c: Set write format, result '0' [Jun 5 11:45:29] VERBOSE[5605] app_queue.c: -- Agent/101 answered SIP/290-0000000b [Jun 5 11:45:29] VERBOSE[5605] res_musiconhold.c: -- Stopped music on hold on SIP/290-0000000b [Jun 5 11:45:29] DEBUG[5605] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:29] DEBUG[5605] channel.c: Set channel Agent/101 to write format ulaw [Jun 5 11:45:29] DEBUG[5605] app_queue.c: Queue '8000' Leave, Channel 'SIP/290-0000000b' [Jun 5 11:45:29] DEBUG[5605] features.c: bridge answer set, chan answer set [Jun 5 11:45:29] DEBUG[5605] features.c: Removing dialed interfaces datastore on Agent/101 since we're bridging [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 5 11:45:29] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for Agent - 101 [Jun 5 11:45:29] DEBUG[5309] devicestate.c: Changing state for Agent/101 - state 3 (Busy) [Jun 5 11:45:29] DEBUG[5309] devicestate.c: device 'Agent/101' state '3' [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Agent/101 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 290 ConnectedLineName: ZoIPer Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: SIP/290-0000000b UniqueID: 1338914728.15 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: Leave Privilege: call,all Channel: SIP/290-0000000b Queue: 8000 Count: 0 Position: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: QUEUEPOSITION Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: BRIDGEPEER Value: Agent/101 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPEER Value: SIP/290-0000000b Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: Agent/101 Uniqueid: 1338914728.16 AccountCode: OldAccountCode: [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: Bridge Privilege: call,all Bridgestate: Link Bridgetype: core Channel1: SIP/290-0000000b Channel2: Agent/101 Uniqueid1: 1338914728.15 Uniqueid2: 1338914728.16 CallerID1: 290 CallerID2: 8000 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: BRIDGEPEER Value: Agent/101 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPEER Value: SIP/290-0000000b Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPVTCALLID Value: qozpzhlflfddxya@eabad.palosanto.com Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: BRIDGEPEER Value: Agent/101 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPEER Value: SIP/290-0000000b Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPVTCALLID Value: qozpzhlflfddxya@eabad.palosanto.com Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: Agent/101 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 290 ConnectedLineName: ZoIPer Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Stop Channel: SIP/290-0000000b UniqueID: 1338914728.15 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: Leave Privilege: call,all Channel: SIP/290-0000000b Queue: 8000 Count: 0 Position: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: QUEUEPOSITION Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: BRIDGEPEER Value: Agent/101 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPEER Value: SIP/290-0000000b Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: Agent/101 Uniqueid: 1338914728.16 AccountCode: OldAccountCode: [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: Bridge Privilege: call,all Bridgestate: Link Bridgetype: core Channel1: SIP/290-0000000b Channel2: Agent/101 Uniqueid1: 1338914728.15 Uniqueid2: 1338914728.16 CallerID1: 290 CallerID2: 8000 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: BRIDGEPEER Value: Agent/101 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPEER Value: SIP/290-0000000b Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPVTCALLID Value: qozpzhlflfddxya@eabad.palosanto.com Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: BRIDGEPEER Value: Agent/101 Uniqueid: 1338914728.15 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPEER Value: SIP/290-0000000b Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: Agent/101 Variable: BRIDGEPVTCALLID Value: qozpzhlflfddxya@eabad.palosanto.com Uniqueid: 1338914728.16 [Jun 5 11:45:29] DEBUG[5351] app_queue.c: Device 'Agent/101' changed to state '3' (Busy) [Jun 5 11:45:29] DEBUG[5605] chan_agent.c: Bridge on 'SIP/300-0000000a' being set to 'Agent/101' (3) [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:29] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] VERBOSE[5331] chan_sip.c: <--- SIP read from UDP:192.168.1.161:5060 ---> OPTIONS sip:192.168.1.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.161:5060;branch=z9hG4bK6f8c9666;rport Max-Forwards: 70 From: "Unknown" ;tag=as57e0c832 To: Contact: Call-ID: 1fa5e81c2b7510536204971e7b66b666@192.168.1.161:5060 CSeq: 102 OPTIONS User-Agent: FPBX-2.8.1(1.8.9.2) Date: Tue, 05 Jun 2012 16:45:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 <-------------> [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 0 [ 32]: OPTIONS sip:192.168.1.66 SIP/2.0 [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.161:5060;branch=z9hG4bK6f8c9666;rport [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 3 [ 58]: From: "Unknown" ;tag=as57e0c832 [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 4 [ 22]: To: [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 5 [ 41]: Contact: [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 6 [ 60]: Call-ID: 1fa5e81c2b7510536204971e7b66b666@192.168.1.161:5060 [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.8.1(1.8.9.2) [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 9 [ 35]: Date: Tue, 05 Jun 2012 16:45:30 GMT [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 11 [ 19]: Supported: replaces [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jun 5 11:45:30] VERBOSE[5331] chan_sip.c: --- (13 headers 0 lines) --- [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: = Looking for Call ID: 1fa5e81c2b7510536204971e7b66b666@192.168.1.161:5060 (Checking From) --From tag as57e0c832 --To-tag [Jun 5 11:45:30] DEBUG[5331] acl.c: For destination '192.168.1.161', our source address is '192.168.1.66'. [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.66:5060 [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Allocating new SIP dialog for 1fa5e81c2b7510536204971e7b66b666@192.168.1.161:5060 - OPTIONS (No RTP) [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jun 5 11:45:30] DEBUG[5331] netsock2.c: Splitting '192.168.1.66' into... [Jun 5 11:45:30] DEBUG[5331] netsock2.c: ...host '192.168.1.66' and port ''. [Jun 5 11:45:30] DEBUG[5331] netsock2.c: Splitting '192.168.1.161' into... [Jun 5 11:45:30] DEBUG[5331] netsock2.c: ...host '192.168.1.161' and port ''. [Jun 5 11:45:30] VERBOSE[5331] chan_sip.c: Looking for s in from-sip-external (domain 192.168.1.66) [Jun 5 11:45:30] VERBOSE[5331] chan_sip.c: <--- Transmitting (NAT) to 192.168.1.161:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.161:5060;branch=z9hG4bK6f8c9666;received=192.168.1.161;rport=5060 From: "Unknown" ;tag=as57e0c832 To: ;tag=as341d0a30 Call-ID: 1fa5e81c2b7510536204971e7b66b666@192.168.1.161:5060 CSeq: 102 OPTIONS Server: FPBX-2.8.1(1.8.13.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Jun 5 11:45:30] DEBUG[5331] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.161:5060 [Jun 5 11:45:30] VERBOSE[5331] chan_sip.c: Scheduling destruction of SIP dialog '1fa5e81c2b7510536204971e7b66b666@192.168.1.161:5060' in 32000 ms (Method: OPTIONS) [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5353] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 192.168.1.179:11795 OurSSRC: 963665539 SentNTP: 1338914730.2295013376 SentRTP: 1639577928 SentPackets: 5275 SentOctets: 844000 ReportBlock: FractionLost: 0 CumulativeLoss: 62 IAJitter: 0.0056 TheirLastSR: 1319387594 DLSR: 2.3050 (sec) [Jun 5 11:45:30] DEBUG[5387] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 192.168.1.179:11795 OurSSRC: 963665539 SentNTP: 1338914730.2295013376 SentRTP: 1639577928 SentPackets: 5275 SentOctets: 844000 ReportBlock: FractionLost: 0 CumulativeLoss: 62 IAJitter: 0.0056 TheirLastSR: 1319387594 DLSR: 2.3050 (sec) [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:30] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:31] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: No remote address on RTP instance '0x18da55f8' so dropping frame [Jun 5 11:45:32] VERBOSE[5331] chan_sip.c: <--- SIP read from UDP:192.168.1.84:5060 ---> BYE sip:8000@192.168.1.66:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKlofztbmn Max-Forwards: 70 To: ;tag=as2cc37702 From: "EHCP" ;tag=jxabg Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 157 BYE User-Agent: Twinkle/1.4.2 Content-Length: 0 <-------------> [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 0 [ 38]: BYE sip:8000@192.168.1.66:5060 SIP/2.0 [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 192.168.1.84;rport;branch=z9hG4bKlofztbmn [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 3 [ 42]: To: ;tag=as2cc37702 [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 4 [ 45]: From: "EHCP" ;tag=jxabg [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 5 [ 44]: Call-ID: qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 6 [ 13]: CSeq: 157 BYE [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 7 [ 25]: User-Agent: Twinkle/1.4.2 [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jun 5 11:45:32] VERBOSE[5331] chan_sip.c: --- (9 headers 0 lines) --- [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: = Looking for Call ID: qozpzhlflfddxya@eabad.palosanto.com (Checking From) --From tag jxabg --To-tag as2cc37702 [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Initializing initreq for method BYE - callid qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:32] DEBUG[5331] netsock2.c: Splitting '192.168.1.84' into... [Jun 5 11:45:32] DEBUG[5331] netsock2.c: ...host '192.168.1.84' and port ''. [Jun 5 11:45:32] VERBOSE[5331] chan_sip.c: Sending to 192.168.1.84:5060 (NAT) [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Setting SIP_ALREADYGONE on dialog qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:32] DEBUG[5331] chan_agent.c: Asked for bridged channel on 'SIP/290-0000000b'/'Agent/101', returning 'SIP/300-0000000a' [Jun 5 11:45:32] DEBUG[5331] chan_agent.c: Asked for bridged channel on 'SIP/290-0000000b'/'Agent/101', returning 'SIP/300-0000000a' [Jun 5 11:45:32] DEBUG[5331] chan_agent.c: Asked for bridged channel on 'SIP/300-0000000a'/'Agent/101', returning 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5331] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x18da4268' [Jun 5 11:45:32] DEBUG[5331] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x18da55f8' [Jun 5 11:45:32] DEBUG[5331] chan_agent.c: Asked for bridged channel on 'SIP/290-0000000b'/'Agent/101', returning 'SIP/300-0000000a' [Jun 5 11:45:32] VERBOSE[5331] chan_sip.c: Scheduling destruction of SIP dialog 'qozpzhlflfddxya@eabad.palosanto.com' in 6400 ms (Method: BYE) [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Received bye, issuing owner hangup [Jun 5 11:45:32] VERBOSE[5331] chan_sip.c: <--- Transmitting (NAT) to 192.168.1.84:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.84;branch=z9hG4bKlofztbmn;received=192.168.1.84;rport=5060 From: "EHCP" ;tag=jxabg To: ;tag=as2cc37702 Call-ID: qozpzhlflfddxya@eabad.palosanto.com CSeq: 157 BYE Server: FPBX-2.8.1(1.8.13.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jun 5 11:45:32] DEBUG[5331] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.84:5060 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOS Value: ssrc=2021976607;themssrc=3975124857;lp=0;rxjitter=0.005782;rxcount=192;txjitter=0.000000;txcount=167;rlp=0;rtt=0.000000 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSBRIDGED Value: ssrc=2021976607;themssrc=3975124857;lp=0;rxjitter=0.005782;rxcount=192;txjitter=0.000000;txcount=167;rlp=0;rtt=0.000000 Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSJITTERBRIDGED Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSLOSSBRIDGED Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSRTTBRIDGED Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOS Value: ssrc=963665539;themssrc=413245395;lp=62;rxjitter=0.005923;rxcount=5354;txjitter=0.000000;txcount=5377;rlp=1;rtt=0.116000 Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSBRIDGED Value: ssrc=963665539;themssrc=413245395;lp=62;rxjitter=0.005923;rxcount=5354;txjitter=0.000000;txcount=5377;rlp=1;rtt=0.116000 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSJITTERBRIDGED Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSLOSSBRIDGED Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSRTTBRIDGED Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPVIDEOQOS Value: ssrc=464057492;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOS Value: ssrc=2021976607;themssrc=3975124857;lp=0;rxjitter=0.005782;rxcount=192;txjitter=0.000000;txcount=167;rlp=0;rtt=0.000000 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSBRIDGED Value: ssrc=2021976607;themssrc=3975124857;lp=0;rxjitter=0.005782;rxcount=192;txjitter=0.000000;txcount=167;rlp=0;rtt=0.000000 Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSJITTERBRIDGED Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSLOSSBRIDGED Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSRTTBRIDGED Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOS Value: ssrc=963665539;themssrc=413245395;lp=62;rxjitter=0.005923;rxcount=5354;txjitter=0.000000;txcount=5377;rlp=1;rtt=0.116000 Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSBRIDGED Value: ssrc=963665539;themssrc=413245395;lp=62;rxjitter=0.005923;rxcount=5354;txjitter=0.000000;txcount=5377;rlp=1;rtt=0.116000 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSJITTERBRIDGED Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSLOSSBRIDGED Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/300-0000000a Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914625.14 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPAUDIOQOSRTTBRIDGED Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: RTPVIDEOQOS Value: ssrc=464057492;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] channel.c: Didn't get a frame from channel: SIP/290-0000000b [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 5 11:45:32] DEBUG[5605] channel.c: Bridge stops bridging channels SIP/290-0000000b and Agent/101 [Jun 5 11:45:32] DEBUG[5605] channel.c: Soft-Hanging up channel 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'Macro' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [h@from-internal:1] Macro("SIP/290-0000000b", "hangupcall") in new stack [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '(null)' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/290-0000000b", "1?endmixmoncheck") in new stack [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Goto (macro-hangupcall,s,9) [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:9] NoOp("SIP/290-0000000b", "End of MIXMON check") in new stack [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'MEETME_RECORDINGFILE' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:10] GotoIf("SIP/290-0000000b", "1?nomeetmemon") in new stack [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Goto (macro-hangupcall,s,15) [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'MEETME_RECORDINGFILE' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:15] NoOp("SIP/290-0000000b", "MEETME_RECORDINGFILE=") in new stack [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'TOUCH_MONITOR_OUTPUT' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:16] GotoIf("SIP/290-0000000b", "1?noautomon") in new stack [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Goto (macro-hangupcall,s,18) [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'TOUCH_MONITOR_OUTPUT' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:18] NoOp("SIP/290-0000000b", "TOUCH_MONITOR_OUTPUT=") in new stack [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'MONITOR_FILENAME' is '/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:19] GotoIf("SIP/290-0000000b", "0?noautomon2") in new stack [Jun 5 11:45:32] DEBUG[5605] pbx.c: Not taking any branch [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'MONITOR_FILENAME' is '/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'System' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:20] System("SIP/290-0000000b", "test -e /var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15*") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Unlink Privilege: call,all Channel1: SIP/290-0000000b Channel2: Agent/101 Uniqueid1: 1338914728.15 Uniqueid2: 1338914728.16 CallerID1: 290 CallerID2: 8000 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: h Priority: 1 Application: Macro AppData: hangupcall Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_IN_HANGUP Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_EXTEN Value: h Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 1 Application: GotoIf AppData: 1?endmixmoncheck Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 9 Application: NoOp AppData: End of MIXMON check Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 10 Application: GotoIf AppData: 1?nomeetmemon Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 15 Application: NoOp AppData: MEETME_RECORDINGFILE= Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 16 Application: GotoIf AppData: 1?noautomon Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 18 Application: NoOp AppData: TOUCH_MONITOR_OUTPUT= Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 19 Application: GotoIf AppData: 0?noautomon2 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 20 Application: System AppData: test -e /var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15* Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Unlink Privilege: call,all Channel1: SIP/290-0000000b Channel2: Agent/101 Uniqueid1: 1338914728.15 Uniqueid2: 1338914728.16 CallerID1: 290 CallerID2: 8000 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: from-internal Extension: h Priority: 1 Application: Macro AppData: hangupcall Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_IN_HANGUP Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_EXTEN Value: h Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 1 Application: GotoIf AppData: 1?endmixmoncheck Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 9 Application: NoOp AppData: End of MIXMON check Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 10 Application: GotoIf AppData: 1?nomeetmemon Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 15 Application: NoOp AppData: MEETME_RECORDINGFILE= Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 16 Application: GotoIf AppData: 1?noautomon Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 18 Application: NoOp AppData: TOUCH_MONITOR_OUTPUT= Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 19 Application: GotoIf AppData: 0?noautomon2 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 20 Application: System AppData: test -e /var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15* Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SYSTEMSTATUS Value: APPERROR Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: SYSTEMSTATUS Value: APPERROR Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: System [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'SYSTEMSTATUS' is 'APPERROR' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:21] NoOp("SIP/290-0000000b", "SYSTEMSTATUS = APPERROR") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 21 Application: NoOp AppData: SYSTEMSTATUS = APPERROR Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 21 Application: NoOp AppData: SYSTEMSTATUS = APPERROR Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'SYSTEMSTATUS' is 'APPERROR' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:22] GotoIf("SIP/290-0000000b", "1?errornoautomon") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 22 Application: GotoIf AppData: 1?errornoautomon Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 22 Application: GotoIf AppData: 1?errornoautomon Uniqueid: 1338914728.15 [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Goto (macro-hangupcall,s,24) [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:24] NoOp("SIP/290-0000000b", "End of MONITOR QUEUE check") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 24 Application: NoOp AppData: End of MONITOR QUEUE check Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 24 Application: NoOp AppData: End of MONITOR QUEUE check Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'MONITOR_FILENAME' is '/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:25] NoOp("SIP/290-0000000b", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 25 Application: NoOp AppData: MONITOR_FILENAME=/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 25 Application: NoOp AppData: MONITOR_FILENAME=/var/spool/asterisk/monitor/q8000-20120605-114528-1338914728.15 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'USE_CONFIRMATION' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'RINGGROUP_INDEX' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'CHANNEL' is 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'UNIQCHAN' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:26] GotoIf("SIP/290-0000000b", "1?skiprg") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 26 Application: GotoIf AppData: 1?skiprg Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 26 Application: GotoIf AppData: 1?skiprg Uniqueid: 1338914728.15 [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Goto (macro-hangupcall,s,29) [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'BLKVM_BASE' is '8000' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'BLKVM_BASE' is '8000' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'CHANNEL' is 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'BLKVM_OVERRIDE' is 'BLKVM/8000/SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '0' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:29] GotoIf("SIP/290-0000000b", "0?skipblkvm") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 29 Application: GotoIf AppData: 0?skipblkvm Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 29 Application: GotoIf AppData: 0?skipblkvm Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Not taking any branch [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'BLKVM_OVERRIDE' is 'BLKVM/8000/SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:30] NoOp("SIP/290-0000000b", "Cleaning Up Block VM Flag: BLKVM/8000/SIP/290-0000000b") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 30 Application: NoOp AppData: Cleaning Up Block VM Flag: BLKVM/8000/SIP/290-0000000b Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 30 Application: NoOp AppData: Cleaning Up Block VM Flag: BLKVM/8000/SIP/290-0000000b Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'BLKVM_OVERRIDE' is 'BLKVM/8000/SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'BLKVM_OVERRIDE' is 'BLKVM/8000/SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: TRUE Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: DB_RESULT Value: TRUE Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'TRUE' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'NoOp' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:31] NoOp("SIP/290-0000000b", "Deleting: BLKVM/8000/SIP/290-0000000b TRUE") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 31 Application: NoOp AppData: Deleting: BLKVM/8000/SIP/290-0000000b TRUE Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 31 Application: NoOp AppData: Deleting: BLKVM/8000/SIP/290-0000000b TRUE Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: Noop [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'FMGRP' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'FMUNIQUE' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'CHANNEL' is 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Result of 'FMUNIQUE' is NULL [Jun 5 11:45:32] DEBUG[5605] pbx.c: Expression result is '1' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'GotoIf' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:32] GotoIf("SIP/290-0000000b", "1?theend") in new stack [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 32 Application: GotoIf AppData: 1?theend Uniqueid: 1338914728.15 [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Goto (macro-hangupcall,s,34) [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Executed application: GotoIf [Jun 5 11:45:32] DEBUG[5605] pbx.c: Launching 'Hangup' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: -- Executing [s@macro-hangupcall:34] Hangup("SIP/290-0000000b", "") in new stack [Jun 5 11:45:32] DEBUG[5605] app_macro.c: Spawn extension (macro-hangupcall,s,34) exited non-zero on 'SIP/290-0000000b' in macro 'hangupcall' [Jun 5 11:45:32] VERBOSE[5605] app_macro.c: == Spawn extension (macro-hangupcall, s, 34) exited non-zero on 'SIP/290-0000000b' in macro 'hangupcall' [Jun 5 11:45:32] DEBUG[5605] features.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/290-0000000b' [Jun 5 11:45:32] VERBOSE[5605] features.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] cdr_mysql.c: Inserting a CDR record. [Jun 5 11:45:32] DEBUG[5605] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2012-06-05 11:45:28','\"ZoIPer\" <290>','290','8000','from-internal','SIP/290-0000000b','Agent/101','Queue','8000,t,,','4','4','ANSWERED','3','1338914728.15') [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '2012-06-05 11:45:28' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '"ZoIPer" <290>' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'from-internal' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'Agent/101' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'Queue' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '8000,t,,' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '4' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '4' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'ANSWERED' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is 'DOCUMENTATION' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '(null)' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '1338914728.15' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '(null)' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '(null)' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '290' [Jun 5 11:45:32] DEBUG[5605] pbx.c: Function result is '8000' [Jun 5 11:45:32] DEBUG[5605] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test,src,dst) VALUES ('2012-06-05 11:45:28','"ZoIPer" <290>','from-internal','SIP/290-0000000b','Agent/101','Queue','8000,t,,','4','4','ANSWERED','DOCUMENTATION','','1338914728.15','','','290','8000') [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 32 Application: GotoIf AppData: 1?theend Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 34 Application: Hangup AppData: Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 0 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 1 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/290-0000000b Context: macro-hangupcall Extension: s Priority: 34 Application: Hangup AppData: Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/290-0000000b Variable: MACRO_DEPTH Value: 0 Uniqueid: 1338914728.15 [Jun 5 11:45:32] DEBUG[5605] channel.c: Hanging up channel 'Agent/101' [Jun 5 11:45:32] DEBUG[5605] chan_agent.c: Hangup called for state Up [Jun 5 11:45:32] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:32] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:32] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jun 5 11:45:32] VERBOSE[5605] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/300-0000000a [Jun 5 11:45:32] DEBUG[5605] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:32] DEBUG[5605] devicestate.c: device 'Agent/101' state '1' [Jun 5 11:45:32] DEBUG[5351] app_queue.c: Device 'Agent/101' changed to state '1' (Not in use) [Jun 5 11:45:32] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for Agent - 101 [Jun 5 11:45:32] DEBUG[5309] devicestate.c: Changing state for Agent/101 - state 0 (Unknown) [Jun 5 11:45:32] DEBUG[5309] devicestate.c: device 'Agent/101' state '0' [Jun 5 11:45:32] DEBUG[5351] app_queue.c: Device 'Agent/101' changed to state '0' (Unknown) [Jun 5 11:45:32] DEBUG[5605] pbx.c: Spawn extension (from-internal,8000,9) exited non-zero on 'SIP/290-0000000b' [Jun 5 11:45:32] VERBOSE[5605] pbx.c: == Spawn extension (from-internal, 8000, 9) exited non-zero on 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] channel.c: Soft-Hanging up channel 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] channel.c: Hanging up channel 'SIP/290-0000000b' [Jun 5 11:45:32] DEBUG[5605] chan_sip.c: Hanging up zombie call. Be scared. [Jun 5 11:45:32] DEBUG[5605] chan_sip.c: update_call_counter(290) - decrement call limit counter on hangup [Jun 5 11:45:32] DEBUG[5605] chan_sip.c: Updating call counter for incoming call [Jun 5 11:45:32] DEBUG[5605] chan_sip.c: Call from peer '290' removed from call limit 2147483647 [Jun 5 11:45:32] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for SIP - 290 [Jun 5 11:45:32] DEBUG[5309] chan_sip.c: Checking device state for peer 290 [Jun 5 11:45:32] DEBUG[5309] devicestate.c: Changing state for SIP/290 - state 1 (Not in use) [Jun 5 11:45:32] DEBUG[5309] devicestate.c: device 'SIP/290' state '1' [Jun 5 11:45:32] DEBUG[5310] app_queue.c: Extension '290@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 5 11:45:32] DEBUG[5351] app_queue.c: Device 'SIP/290' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x18da4268' [Jun 5 11:45:32] DEBUG[5605] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x18da55f8' [Jun 5 11:45:32] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for SIP - 290 [Jun 5 11:45:32] DEBUG[5309] chan_sip.c: Checking device state for peer 290 [Jun 5 11:45:32] DEBUG[5309] devicestate.c: Changing state for SIP/290 - state 1 (Not in use) [Jun 5 11:45:32] DEBUG[5309] devicestate.c: device 'SIP/290' state '1' [Jun 5 11:45:32] DEBUG[5351] app_queue.c: Device 'SIP/290' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Start Channel: SIP/300-0000000a UniqueID: 1338914625.14 Class: default [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Agent/101 Uniqueid: 1338914728.16 CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 290 ConnectedLineName: ZoIPer Cause: 0 Cause-txt: Unknown [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 290 Context: ext-local Hint: SIP/290 Status: 0 [Jun 5 11:45:32] DEBUG[5353] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/290-0000000b Uniqueid: 1338914728.15 CallerIDNum: 290 CallerIDName: ZoIPer ConnectedLineNum: ConnectedLineName: Cause: 16 Cause-txt: Normal Clearing [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: MusicOnHold Privilege: call,all State: Start Channel: SIP/300-0000000a UniqueID: 1338914625.14 Class: default [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: Agent/101 Uniqueid: 1338914728.16 CallerIDNum: 8000 CallerIDName: ConnectedLineNum: 290 ConnectedLineName: ZoIPer Cause: 0 Cause-txt: Unknown [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 290 Context: ext-local Hint: SIP/290 Status: 0 [Jun 5 11:45:32] DEBUG[5387] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/290-0000000b Uniqueid: 1338914728.15 CallerIDNum: 290 CallerIDName: ZoIPer ConnectedLineNum: ConnectedLineName: Cause: 16 Cause-txt: Normal Clearing [Jun 5 11:45:32] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format gsm [Jun 5 11:45:32] DEBUG[5589] res_musiconhold.c: SIP/300-0000000a Opened file 1 '/var/lib/asterisk/mohmp3//manolo_camp-morning_coffee' [Jun 5 11:45:32] DEBUG[5589] res_rtp_asterisk.c: Difference is 904, ms is 133 [Jun 5 11:45:33] DEBUG[5589] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jun 5 11:45:33] DEBUG[5589] res_rtp_asterisk.c: Got RTCP report of 96 bytes [Jun 5 11:45:33] DEBUG[5353] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.1.179:11795 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 83886080 FractionLost: 0 PacketsLost: 5 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 186 LastSR: 46634.820403860945240064 DLSR: 2.9199(sec) RTT: 105(sec) [Jun 5 11:45:33] DEBUG[5387] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.1.179:11795 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 83886080 FractionLost: 0 PacketsLost: 5 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 186 LastSR: 46634.820403860945240064 DLSR: 2.9199(sec) RTT: 105(sec) [Jun 5 11:45:33] VERBOSE[5589] res_musiconhold.c: -- Stopped music on hold on SIP/300-0000000a [Jun 5 11:45:33] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:33] DEBUG[5589] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:33] DEBUG[5589] channel.c: Stopped silence generator on 'SIP/300-0000000a' [Jun 5 11:45:33] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:33] DEBUG[5589] chan_agent.c: Wrapup time for 101 expired! [Jun 5 11:45:33] DEBUG[5589] devicestate.c: device 'Agent/101' state '1' [Jun 5 11:45:33] DEBUG[5589] chan_agent.c: Checking availability of '101' [Jun 5 11:45:33] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:33] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:33] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:33] DEBUG[5351] app_queue.c: Device 'Agent/101' changed to state '1' (Not in use) [Jun 5 11:45:34] DEBUG[5353] manager.c: Running action 'Command' [Jun 5 11:45:34] DEBUG[5589] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:34] DEBUG[5589] channel.c: Stopped silence generator on 'SIP/300-0000000a' [Jun 5 11:45:34] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:34] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:34] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:34] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:35] DEBUG[5353] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 192.168.1.179:11795 OurSSRC: 963665539 SentNTP: 1338914735.2295386112 SentRTP: 1639617712 SentPackets: 5518 SentOctets: 882880 ReportBlock: FractionLost: 0 CumulativeLoss: 62 IAJitter: 0.0060 TheirLastSR: 1319736901 DLSR: 1.9740 (sec) [Jun 5 11:45:35] DEBUG[5387] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 192.168.1.179:11795 OurSSRC: 963665539 SentNTP: 1338914735.2295386112 SentRTP: 1639617712 SentPackets: 5518 SentOctets: 882880 ReportBlock: FractionLost: 0 CumulativeLoss: 62 IAJitter: 0.0060 TheirLastSR: 1319736901 DLSR: 1.9740 (sec) [Jun 5 11:45:35] DEBUG[5589] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:35] DEBUG[5589] channel.c: Stopped silence generator on 'SIP/300-0000000a' [Jun 5 11:45:35] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:35] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:35] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:35] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:37] DEBUG[5589] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:37] DEBUG[5589] channel.c: Stopped silence generator on 'SIP/300-0000000a' [Jun 5 11:45:37] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:37] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:37] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:37] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:37] DEBUG[5332] sig_wat.c: Span 1:Signal strength:(-53)dBm (BER:less than 0.2%) [Jun 5 11:45:38] DEBUG[5589] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:38] DEBUG[5589] channel.c: Stopped silence generator on 'SIP/300-0000000a' [Jun 5 11:45:38] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:38] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:38] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:38] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:38] DEBUG[5589] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jun 5 11:45:38] DEBUG[5589] res_rtp_asterisk.c: Got RTCP report of 96 bytes [Jun 5 11:45:38] DEBUG[5353] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.1.179:11795 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 83886080 FractionLost: 0 PacketsLost: 5 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 159 LastSR: 46639.820491823486074880 DLSR: 3.2959(sec) RTT: 93(sec) [Jun 5 11:45:38] DEBUG[5387] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.1.179:11795 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 83886080 FractionLost: 0 PacketsLost: 5 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 159 LastSR: 46639.820491823486074880 DLSR: 3.2959(sec) RTT: 93(sec) [Jun 5 11:45:38] DEBUG[5331] chan_sip.c: Auto destroying SIP dialog 'qozpzhlflfddxya@eabad.palosanto.com' [Jun 5 11:45:38] DEBUG[5331] chan_sip.c: Destroying SIP dialog qozpzhlflfddxya@eabad.palosanto.com [Jun 5 11:45:38] VERBOSE[5331] chan_sip.c: Really destroying SIP dialog 'qozpzhlflfddxya@eabad.palosanto.com' Method: BYE [Jun 5 11:45:38] DEBUG[5331] rtp_engine.c: Destroyed RTP instance '0x18da4268' [Jun 5 11:45:38] DEBUG[5331] rtp_engine.c: Destroyed RTP instance '0x18da55f8' [Jun 5 11:45:39] DEBUG[5589] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 5 11:45:39] DEBUG[5589] channel.c: Stopped silence generator on 'SIP/300-0000000a' [Jun 5 11:45:39] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format ulaw [Jun 5 11:45:39] DEBUG[5589] channel.c: Set channel SIP/300-0000000a to write format slin [Jun 5 11:45:39] DEBUG[5589] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 5 11:45:39] DEBUG[5589] channel.c: Started silence generator on 'SIP/300-0000000a' [Jun 5 11:45:39] DEBUG[5326] chan_iax2.c: Determining if address 127.0.0.1 with username 501 requires calltoken validation. Optional = 1 calltoken_required = 0 [Jun 5 11:45:39] DEBUG[5326] chan_iax2.c: ip callno count incremented to 3 for 127.0.0.1 [Jun 5 11:45:39] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for IAX2 - 501 [Jun 5 11:45:39] DEBUG[5309] chan_iax2.c: Checking device state for device 501 [Jun 5 11:45:39] DEBUG[5309] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 501? addr=2130706433, defaddr=0 maxms=2000, lastms=1 [Jun 5 11:45:39] DEBUG[5309] devicestate.c: Changing state for IAX2/501 - state 0 (Unknown) [Jun 5 11:45:39] DEBUG[5309] devicestate.c: device 'IAX2/501' state '0' [Jun 5 11:45:39] DEBUG[5310] devicestate.c: No provider found, checking channel drivers for IAX2 - 501 [Jun 5 11:45:39] DEBUG[5310] chan_iax2.c: Checking device state for device 501 [Jun 5 11:45:39] DEBUG[5310] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 501? addr=2130706433, defaddr=0 maxms=2000, lastms=1 [Jun 5 11:45:39] DEBUG[5351] app_queue.c: Device 'IAX2/501' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 5 11:45:39] DEBUG[5309] devicestate.c: No provider found, checking channel drivers for IAX2 - 501 [Jun 5 11:45:39] DEBUG[5309] chan_iax2.c: Checking device state for device 501 [Jun 5 11:45:39] DEBUG[5309] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 501? addr=2130706433, defaddr=0 maxms=2000, lastms=1 [Jun 5 11:45:39] DEBUG[5309] devicestate.c: Changing state for IAX2/501 - state 0 (Unknown) [Jun 5 11:45:39] DEBUG[5309] devicestate.c: device 'IAX2/501' state '0' [Jun 5 11:45:39] DEBUG[5310] devicestate.c: No provider found, checking channel drivers for IAX2 - 501 [Jun 5 11:45:39] DEBUG[5310] chan_iax2.c: Checking device state for device 501 [Jun 5 11:45:39] DEBUG[5310] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 501? addr=2130706433, defaddr=0 maxms=2000, lastms=1 [Jun 5 11:45:39] DEBUG[5351] app_queue.c: Device 'IAX2/501' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 5 11:45:39] NOTICE[5326] chan_iax2.c: Restricting registration for peer '501' to 60 seconds (requested 300) [Jun 5 11:45:39] DEBUG[5326] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds