[Nov 1 23:59:35] DEBUG[7866] chan_sip.c: Session timer stopped: -1 - 2cae43ff51b709451cec76dd4af0aafa@192.168.1.10:5060 [Nov 1 23:59:35] DEBUG[7866] chan_sip.c: Destroying SIP dialog 2cae43ff51b709451cec76dd4af0aafa@192.168.1.10:5060 [Nov 1 23:59:35] DEBUG[7881] manager.c: Examining event: Event: JabberEvent Privilege: user,all Account: userasterisk Packet: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 43]: INVITE sip:2155555757@192.168.1.10:5060 SIP/2.0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 51]: Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK46BD24 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 68]: From: "WIRELESS CALLER" ;tag=1B3646CB-229E [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 29]: To: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 35]: Date: Fri, 02 Nov 2012 04:05:55 GMT [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 52]: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 32]: Supported: 100rel,timer,replaces [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 12]: Min-SE: 1800 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 53]: Cisco-Guid: 1869229936-601428450-2408879584-125411504 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 9 [ 37]: User-Agent: Cisco-SIPGateway/IOS-12.x [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 10 [112]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 11 [ 16]: CSeq: 111 INVITE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 12 [ 16]: Max-Forwards: 70 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 13 [ 97]: Remote-Party-ID: "WIRELESS CALLER" ;party=calling;screen=no;privacy=off [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 14 [ 21]: Timestamp: 1351829155 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 15 [ 40]: Contact: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 16 [ 12]: Expires: 180 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 17 [ 29]: Allow-Events: telephone-event [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 18 [ 29]: Content-Type: application/sdp [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 19 [ 19]: Content-Length: 434 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 20 [ 0]: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 0 [ 3]: v=0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 1 [ 56]: o=CiscoSystemsSIP-GW-UserAgent 4498 9213 IN IP4 192.168.1.7 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 2 [ 10]: s=SIP Call [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 3 [ 17]: c=IN IP4 192.168.1.7 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 5 [ 31]: m=audio 16674 RTP/AVP 0 100 111 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 6 [ 17]: c=IN IP4 192.168.1.7 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 8 [ 23]: a=rtpmap:100 X-NSE/8000 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 9 [ 26]: a=fmtp:100 192-194,200-202 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 10 [ 33]: a=rtpmap:111 telephone-event/8000 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 11 [ 15]: a=fmtp:111 0-16 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 12 [ 10]: a=ptime:20 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 13 [ 9]: a=X-sqn:0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 14 [ 28]: a=X-cap: 1 audio RTP/AVP 100 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 15 [ 33]: a=X-cpar: a=rtpmap:100 X-NSE/8000 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 16 [ 36]: a=X-cpar: a=fmtp:100 192-194,200-202 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Body 17 [ 26]: a=X-cap: 2 image udptl t38 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 (Checking From) --From tag 1B3646CB-229E --To-tag [Nov 1 23:59:38] DEBUG[7866] acl.c: For destination '192.168.1.7', our source address is '192.168.1.10'. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Allocating new SIP dialog for 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 - INVITE (No RTP) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Begin: parsing SIP "Supported: 100rel,timer,replaces" [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Found SIP option: -100rel- [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Matched SIP option: 100rel [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Found SIP option: -timer- [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Matched SIP option: timer [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Found SIP option: -replaces- [Nov 1 23:59:38] DEBUG[7866] sip/reqresp_parser.c: Matched SIP option: replaces [Nov 1 23:59:38] DEBUG[7866] netsock2.c: Splitting '192.168.1.7:5060' into... [Nov 1 23:59:38] DEBUG[7866] netsock2.c: ...host '192.168.1.7' and port '5060'. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Initializing initreq for method INVITE - callid 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:38] DEBUG[7866] netsock2.c: Splitting '192.168.1.7' into... [Nov 1 23:59:38] DEBUG[7866] netsock2.c: ...host '192.168.1.7' and port ''. [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6233150' [Nov 1 23:59:38] DEBUG[7866] res_rtp_asterisk.c: Allocated port 10000 for RTP instance '0xb6233150' [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: RTP instance '0xb6233150' is setup and ready to go [Nov 1 23:59:38] DEBUG[7866] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6233150' [Nov 1 23:59:38] VERBOSE[7866] netsock2.c: == Using SIP RTP CoS mark 5 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Setting NAT on RTP to On [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 4498 9213 IN IP4 192.168.1.7... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] netsock2.c: Splitting '192.168.1.7' into... [Nov 1 23:59:38] DEBUG[7866] netsock2.c: ...host '192.168.1.7' and port ''. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.7... OK. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Setting payload 0 based on m type on 0xb638f3b4 [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Setting payload 111 based on m type on 0xb638f3b4 [Nov 1 23:59:38] DEBUG[7866] netsock2.c: Splitting '192.168.1.7' into... [Nov 1 23:59:38] DEBUG[7866] netsock2.c: ...host '192.168.1.7' and port ''. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.7... OK. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Unsetting payload 100 on 0xb638f3b4 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 X-NSE/8000... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=fmtp:100 192-194,200-202... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 telephone-event/8000... OK. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 0-16... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=X-sqn:0... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=X-cap: 1 audio RTP/AVP 100... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=X-cpar: a=rtpmap:100 X-NSE/8000... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=X-cpar: a=fmtp:100 192-194,200-202... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=X-cap: 2 image udptl t38... UNSUPPORTED OR FAILED. [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Incorporating payload 0 on 0xb638f3b4 [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Incorporating payload 111 on 0xb638f3b4 [Nov 1 23:59:38] DEBUG[7866] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6233150' [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Copying payload 0 from 0xb638f3b4 to 0xb62332fc [Nov 1 23:59:38] DEBUG[7866] rtp_engine.c: Copying payload 111 from 0xb638f3b4 to 0xb62332fc [Nov 1 23:59:38] DEBUG[7866] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb6233150' [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Checking SIP call limits for device [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Updating call counter for incoming call [Nov 1 23:59:38] DEBUG[7866] netsock2.c: Splitting '192.168.1.10:5060' into... [Nov 1 23:59:38] DEBUG[7866] netsock2.c: ...host '192.168.1.10' and port ''. [Nov 1 23:59:38] DEBUG[7866] netsock2.c: Splitting '192.168.1.7' into... [Nov 1 23:59:38] DEBUG[7866] netsock2.c: ...host '192.168.1.7' and port ''. [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/vgw1-00000208 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 16105551111 CallerIDName: WIRELESS CALLER AccountCode: Exten: 2155555757 Context: inbound Uniqueid: 1351828778.679 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: This channel will not be able to handle video. [Nov 1 23:59:38] DEBUG[7866] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 1 23:59:38] DEBUG[7866] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: build_route: Contact hop: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP/vgw1-00000208: New call is still down.... Trying... [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.7:62151 [Nov 1 23:59:38] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - vgw1 [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/vgw1-00000208 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 16105551111 CallerIDName: WIRELESS CALLER ConnectedLineNum: ConnectedLineName: Uniqueid: 1351828778.679 [Nov 1 23:59:38] DEBUG[7855] chan_sip.c: Checking device state for peer vgw1 [Nov 1 23:59:38] DEBUG[7855] devicestate.c: Changing state for SIP/vgw1 - state 1 (Not in use) [Nov 1 23:59:38] DEBUG[7855] devicestate.c: device 'SIP/vgw1' state '1' [Nov 1 23:59:38] DEBUG[22132] pbx.c: Result of 'EXTEN' is '2155555757' [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'Set' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [2155555757@inbound:1] Set("SIP/vgw1-00000208", "DNIS=2155555757") in new stack [Nov 1 23:59:38] DEBUG[22132] pbx.c: Function result is '16105551111' [Nov 1 23:59:38] DEBUG[22132] func_strings.c: c1=48, c2=57 [Nov 1 23:59:38] DEBUG[22132] func_strings.c: c1=45, consumed=2, args.allowed=\- [Nov 1 23:59:38] DEBUG[22132] func_strings.c: Allowed: -0123456789 [Nov 1 23:59:38] DEBUG[22132] pbx.c: Function result is '6105551111' [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'Set' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [2155555757@inbound:2] Set("SIP/vgw1-00000208", "CALLERID(num)=6105551111") in new stack [Nov 1 23:59:38] DEBUG[22132] pbx.c: Function result is '6105551111' [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/vgw1-00000208 CallerIDNum: 6105551111 CallerIDName: WIRELESS CALLER Uniqueid: 1351828778.679 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 1 23:59:38] DEBUG[22132] pbx.c: Function result is '1' [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'GotoIf' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [2155555757@inbound:3] GotoIf("SIP/vgw1-00000208", "1?override") in new stack [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Goto (inbound,2155555757,12) [Nov 1 23:59:38] DEBUG[22132] pbx.c: Function result is '6105551111' [Nov 1 23:59:38] DEBUG[22132] pbx.c: Function result is 'Jeremy Cell' [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'Set' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [2155555757@inbound:12] Set("SIP/vgw1-00000208", "CALLERID(name)=Jeremy Cell") in new stack [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'Goto' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [2155555757@inbound:13] Goto("SIP/vgw1-00000208", "attendant,s,1") in new stack [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Goto (attendant,s,1) [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'Answer' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [s@attendant:1] Answer("SIP/vgw1-00000208", "") in new stack [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/vgw1-00000208 CallerIDNum: 6105551111 CallerIDName: Jeremy Cell Uniqueid: 1351828778.679 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 1 23:59:38] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - vgw1 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: SIP answering channel: SIP/vgw1-00000208 [Nov 1 23:59:38] DEBUG[7855] chan_sip.c: Checking device state for peer vgw1 [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:38] DEBUG[7855] devicestate.c: Changing state for SIP/vgw1 - state 1 (Not in use) [Nov 1 23:59:38] DEBUG[7855] devicestate.c: device 'SIP/vgw1' state '1' [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Setting framing from config on incoming call [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/vgw1-00000208 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6105551111 CallerIDName: Jeremy Cell ConnectedLineNum: ConnectedLineName: Uniqueid: 1351828778.679 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: -- Done with adding codecs to SDP [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137592 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.7:62151 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 40]: ACK sip:2155555757@192.168.1.10:5060 SIP/2.0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 51]: Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK46CC07 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 68]: From: "WIRELESS CALLER" ;tag=1B3646CB-229E [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 44]: To: ;tag=as6e1fb859 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 35]: Date: Fri, 02 Nov 2012 04:05:55 GMT [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 52]: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 13]: CSeq: 111 ACK [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 (Checking From) --From tag 1B3646CB-229E --To-tag as6e1fb859 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137592 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Stopping retransmission on '6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7' of Response 111: Match Found [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=3.86E+08, Et=9.97E+09, s/n= 0.04 [Nov 1 23:59:38] DEBUG[22132] pbx.c: Launching 'Dial' [Nov 1 23:59:38] VERBOSE[22132] pbx.c: -- Executing [s@attendant:2] Dial("SIP/vgw1-00000208", "SIP/111&SIP/112") in new stack [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Allocating new SIP dialog for 39a44ffd121399cb585ae5a15bef7bae@192.168.1.10:5060 - INVITE (No RTP) [Nov 1 23:59:38] DEBUG[22132] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x922fd48' [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Allocated port 10024 for RTP instance '0x922fd48' [Nov 1 23:59:38] DEBUG[22132] rtp_engine.c: RTP instance '0x922fd48' is setup and ready to go [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x922fd48' [Nov 1 23:59:38] VERBOSE[22132] netsock2.c: == Using SIP RTP CoS mark 5 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Setting NAT on RTP to On [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Nov 1 23:59:38] DEBUG[22132] acl.c: For destination '192.168.1.111', our source address is '192.168.1.10'. [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/111-00000209 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 111 CallerIDName: Jeremy Office AccountCode: Exten: Context: extensions Uniqueid: 1351828778.680 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: This channel will not be able to handle video. [Nov 1 23:59:38] DEBUG[22132] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 1 23:59:38] DEBUG[22132] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALEDTIME. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable ANSWEREDTIME. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALEDPEERNAME. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALEDPEERNUMBER. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALSTATUS. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DB_RESULT. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DNIS. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable SIPCALLID. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable SIPDOMAIN. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable SIPURI. [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Outgoing Call for 111 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Updating call counter for outgoing call [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: -- Done with adding codecs to SDP [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Initializing initreq for method INVITE - callid 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 0 [ 33]: INVITE sip:111@192.168.1.111 SIP/2.0 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK593bd998;rport [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 3 [ 60]: From: "Jeremy Cell" ;tag=as21490600 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 4 [ 24]: To: [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 5 [ 39]: Contact: [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 6 [ 55]: Call-ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 9 [ 35]: Date: Fri, 02 Nov 2012 03:59:38 GMT [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 10 [ 21]: Session-Expires: 7200 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 12 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 14 [ 92]: Remote-Party-ID: "Jeremy Cell" ;party=calling;privacy=off;screen=no [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 15 [ 29]: Content-Type: application/sdp [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137594 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.111:5060 [Nov 1 23:59:38] VERBOSE[22132] app_dial.c: -- Called SIP/111 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: Begin Channel: SIP/vgw1-00000208 Destination: SIP/111-00000209 CallerIDNum: 6105551111 CallerIDName: Jeremy Cell ConnectedLineNum: ConnectedLineName: UniqueID: 1351828778.679 DestUniqueID: 1351828778.680 Dialstring: 111 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Allocating new SIP dialog for 020bbbec15e3c0950b9fc3dc36dd01d6@192.168.1.10:5060 - INVITE (No RTP) [Nov 1 23:59:38] DEBUG[22132] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x922e750' [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Allocated port 10092 for RTP instance '0x922e750' [Nov 1 23:59:38] DEBUG[22132] rtp_engine.c: RTP instance '0x922e750' is setup and ready to go [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x922e750' [Nov 1 23:59:38] VERBOSE[22132] netsock2.c: == Using SIP RTP CoS mark 5 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Setting NAT on RTP to On [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Nov 1 23:59:38] DEBUG[22132] acl.c: For destination '192.168.1.112', our source address is '192.168.1.10'. [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/112-0000020a ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 112 CallerIDName: Great Rm AccountCode: Exten: Context: extensions Uniqueid: 1351828778.681 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: This channel will not be able to handle video. [Nov 1 23:59:38] DEBUG[22132] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 1 23:59:38] DEBUG[22132] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALEDTIME. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable ANSWEREDTIME. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALEDPEERNAME. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALEDPEERNUMBER. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DIALSTATUS. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DB_RESULT. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable DNIS. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable SIPCALLID. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable SIPDOMAIN. [Nov 1 23:59:38] DEBUG[22132] channel.c: Not copying variable SIPURI. [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Outgoing Call for 112 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Updating call counter for outgoing call [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: -- Done with adding codecs to SDP [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Initializing initreq for method INVITE - callid 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 0 [ 52]: INVITE sip:112@192.168.1.112:5060;transport=udp SIP/2.0 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK4f64e6f1;rport [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 3 [ 60]: From: "Jeremy Cell" ;tag=as4c33f92c [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 4 [ 43]: To: [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 5 [ 39]: Contact: [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 6 [ 55]: Call-ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 9 [ 35]: Date: Fri, 02 Nov 2012 03:59:38 GMT [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 10 [ 21]: Session-Expires: 7200 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 12 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 14 [ 92]: Remote-Party-ID: "Jeremy Cell" ;party=calling;privacy=off;screen=no [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Header 15 [ 29]: Content-Type: application/sdp [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137596 [Nov 1 23:59:38] DEBUG[22132] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.112:5060 [Nov 1 23:59:38] VERBOSE[22132] app_dial.c: -- Called SIP/112 [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: Begin Channel: SIP/vgw1-00000208 Destination: SIP/112-0000020a CallerIDNum: 6105551111 CallerIDName: Jeremy Cell ConnectedLineNum: ConnectedLineName: UniqueID: 1351828778.679 DestUniqueID: 1351828778.681 Dialstring: 112 [Nov 1 23:59:38] VERBOSE[22132] app_dial.c: -- SIP/111-00000209 connected line has changed. Saving it until answer for SIP/vgw1-00000208 [Nov 1 23:59:38] VERBOSE[22132] app_dial.c: -- SIP/112-0000020a connected line has changed. Saving it until answer for SIP/vgw1-00000208 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.74E+06, Et=1.24E+08, s/n= 0.01 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.49E+05, Et=1.59E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.83E+06, Et=1.22E+08, s/n= 0.02 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=8.13E+05, Et=1.35E+08, s/n= 0.01 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK593bd998;rport [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as21490600 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 46]: To: ;tag=4FDF88CB-F853091C [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 55]: Call-ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 29]: Contact: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/3.1.6.0017 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 (Checking To) --From tag as21490600 --To-tag 4FDF88CB-F853091C [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: *** SIP TIMER: Cancelling retransmission #137594 - INVITE (got response) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP response 100 to standard invite [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=4.72E+05, Et=1.48E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=9.91E+09, Et=1.46E+12, s/n= 0.01 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP TIMER: Rescheduling retransmission #137596 (1) INVITE - 5 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 222 ms (t1 111 ms (Retrans id #137596)) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.112:5060 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=2.57E+06, Et=6.57E+10, s/n= 0.00 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK4f64e6f1;rport [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as4c33f92c [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 43]: To: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 55]: Call-ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 35]: Date: Fri, 02 Nov 2012 04:08:11 GMT [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 25]: Server: Cisco-CP7940G/8.0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 48]: Contact: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 9 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 (Checking To) --From tag as4c33f92c --To-tag [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: *** SIP TIMER: Cancelling retransmission #137596 - INVITE (got response) [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '541c001e3392734f67235180750a0423@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP response 100 to standard invite [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=3.74E+06, Et=1.14E+10, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.31E+06, Et=9.38E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=5.59E+04, Et=3.34E+07, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.16E+05, Et=9.21E+07, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=2.05E+05, Et=1.15E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.35E+05, Et=1.14E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK4f64e6f1;rport [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as4c33f92c [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 43]: To: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 55]: Call-ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 35]: Date: Fri, 02 Nov 2012 04:08:11 GMT [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 25]: Server: Cisco-CP7940G/8.0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 48]: Contact: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 9 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 (Checking To) --From tag as4c33f92c --To-tag [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '541c001e3392734f67235180750a0423@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP response 100 to standard invite [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.51E+05, Et=2.56E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=4.26E+05, Et=1.78E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK593bd998;rport [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as21490600 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 46]: To: ;tag=4FDF88CB-F853091C [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 55]: Call-ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 29]: Contact: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/3.1.6.0017 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 34]: Allow-Events: talk,hold,conference [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 (Checking To) --From tag as21490600 --To-tag 4FDF88CB-F853091C [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP response 180 to standard invite [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: build_route: Contact hop: [Nov 1 23:59:38] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 1 23:59:38] DEBUG[7855] chan_sip.c: Checking device state for peer 111 [Nov 1 23:59:38] DEBUG[7855] devicestate.c: Changing state for SIP/111 - state 1 (Not in use) [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/111-00000209 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 111 CallerIDName: Jeremy Office ConnectedLineNum: 6105551111 ConnectedLineName: Jeremy Cell Uniqueid: 1351828778.680 [Nov 1 23:59:38] DEBUG[7855] devicestate.c: device 'SIP/111' state '1' [Nov 1 23:59:38] VERBOSE[22132] app_dial.c: -- SIP/111-00000209 is ringing [Nov 1 23:59:38] DEBUG[22132] channel.c: Driver for channel 'SIP/vgw1-00000208' does not support indication 3, emulating it [Nov 1 23:59:38] DEBUG[22132] channel.c: Set channel SIP/vgw1-00000208 to write format slin [Nov 1 23:59:38] DEBUG[22132] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.60E+05, Et=1.30E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Nov 1 23:59:38] DEBUG[22132] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.53E+05, Et=1.31E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK4f64e6f1;rport [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as4c33f92c [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 3 [ 81]: To: ;tag=0013c401d7df384b16efc379-1544e634 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 4 [ 55]: Call-ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 5 [ 35]: Date: Fri, 02 Nov 2012 04:08:11 GMT [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 7 [ 25]: Server: Cisco-CP7940G/8.0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 8 [ 48]: Contact: [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 9 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: = Looking for Call ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 (Checking To) --From tag as4c33f92c --To-tag 0013c401d7df384b16efc379-1544e634 [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '541c001e3392734f67235180750a0423@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: SIP response 180 to standard invite [Nov 1 23:59:38] DEBUG[7866] chan_sip.c: build_route: Contact hop: [Nov 1 23:59:38] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 112 [Nov 1 23:59:38] DEBUG[7855] chan_sip.c: Checking device state for peer 112 [Nov 1 23:59:38] DEBUG[7881] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/112-0000020a ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 112 CallerIDName: Great Rm ConnectedLineNum: 6105551111 ConnectedLineName: Jeremy Cell Uniqueid: 1351828778.681 [Nov 1 23:59:38] DEBUG[7855] devicestate.c: Changing state for SIP/112 - state 1 (Not in use) [Nov 1 23:59:38] DEBUG[7855] devicestate.c: device 'SIP/112' state '1' [Nov 1 23:59:38] VERBOSE[22132] app_dial.c: -- SIP/112-0000020a is ringing [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=2.07E+05, Et=1.51E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=4.33E+05, Et=1.32E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=9.64E+04, Et=1.59E+08, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=4.65E+06, Et=8.74E+08, s/n= 0.01 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.76E+05, Et=1.41E+07, s/n= 0.01 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=2.12E+05, Et=1.32E+07, s/n= 0.02 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.68E+04, Et=1.36E+07, s/n= 0.00 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.33E+05, Et=1.34E+07, s/n= 0.01 [Nov 1 23:59:38] DEBUG[22132] dsp.c: tone 1100, Ew=1.07E+05, Et=1.34E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.63E+05, Et=1.77E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.01E+05, Et=2.58E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=3.83E+05, Et=2.23E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.16E+05, Et=3.18E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.92E+05, Et=2.39E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.85E+05, Et=2.56E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=3.70E+05, Et=3.09E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=3.63E+05, Et=2.67E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=6.31E+05, Et=4.41E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.56E+06, Et=7.17E+07, s/n= 0.04 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.18E+05, Et=1.30E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=8.98E+04, Et=1.30E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.14E+06, Et=1.37E+07, s/n= 0.09 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=6.72E+05, Et=1.39E+07, s/n= 0.05 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.42E+05, Et=1.33E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.39E+05, Et=1.35E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=8.20E+05, Et=1.35E+07, s/n= 0.06 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.71E+05, Et=1.39E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=4.75E+05, Et=1.33E+07, s/n= 0.04 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=3.70E+05, Et=1.34E+07, s/n= 0.03 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=4.58E+05, Et=1.37E+07, s/n= 0.03 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=6.37E+05, Et=1.30E+07, s/n= 0.05 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.43E+05, Et=1.39E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.62E+05, Et=1.33E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=3.21E+05, Et=1.37E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.83E+05, Et=1.36E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.72E+04, Et=1.30E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.89E+05, Et=1.43E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=3.58E+05, Et=1.25E+07, s/n= 0.03 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.32E+03, Et=1.44E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.25E+05, Et=1.32E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=6.67E+04, Et=1.33E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.74E+05, Et=1.36E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.10E+05, Et=1.35E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=9.58E+05, Et=1.35E+07, s/n= 0.08 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=5.65E+04, Et=1.61E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=4.05E+05, Et=2.92E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.91E+05, Et=1.33E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.57E+05, Et=1.35E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.14E+05, Et=1.40E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.01E+05, Et=1.35E+07, s/n= 0.02 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.82E+05, Et=1.31E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.04E+05, Et=1.37E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=9.88E+05, Et=1.36E+07, s/n= 0.08 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=5.04E+05, Et=1.31E+07, s/n= 0.04 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=6.27E+04, Et=1.37E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=2.06E+04, Et=1.65E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.26E+05, Et=2.12E+07, s/n= 0.01 [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=1.87E+05, Et=6.72E+07, s/n= 0.00 [Nov 1 23:59:39] DEBUG[7866] chan_sip.c: Header 0 [ 0]: [Nov 1 23:59:39] DEBUG[22132] dsp.c: tone 1100, Ew=6.47E+05, Et=6.07E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.83E+05, Et=1.53E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.50E+05, Et=1.60E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.05E+05, Et=7.27E+07, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.45E+06, Et=1.67E+07, s/n= 0.09 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.23E+05, Et=5.73E+07, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.45E+05, Et=7.76E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=3.76E+05, Et=3.05E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.74E+05, Et=2.60E+07, s/n= 0.02 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.69E+05, Et=1.67E+07, s/n= 0.02 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=7.29E+04, Et=2.50E+07, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=3.04E+06, Et=7.06E+07, s/n= 0.04 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.10E+06, Et=5.04E+07, s/n= 0.04 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.25E+05, Et=1.41E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.30E+10, Et=1.93E+11, s/n= 0.07 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=4.42E+07, Et=6.72E+09, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.23E+08, Et=2.63E+09, s/n= 0.05 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.57E+08, Et=2.57E+11, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.79E+07, Et=4.70E+10, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=3.70E+06, Et=3.21E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.64E+07, Et=1.21E+10, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.53E+07, Et=7.34E+09, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=3.66E+06, Et=3.97E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=6.78E+06, Et=4.72E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.12E+07, Et=2.39E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.92E+06, Et=1.78E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=3.82E+05, Et=1.88E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.26E+05, Et=1.28E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.03E+06, Et=8.33E+08, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.91E+05, Et=1.40E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=8.14E+05, Et=1.57E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=9.22E+05, Et=1.53E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=6.83E+05, Et=1.45E+09, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.67E+05, Et=7.45E+08, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=3.76E+05, Et=2.99E+08, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.94E+05, Et=4.37E+08, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=4.05E+05, Et=1.84E+08, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.20E+06, Et=5.06E+07, s/n= 0.05 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.31E+06, Et=3.86E+07, s/n= 0.06 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=9.14E+04, Et=1.38E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=8.60E+04, Et=1.51E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.90E+05, Et=1.40E+07, s/n= 0.02 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.43E+05, Et=1.45E+07, s/n= 0.02 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.78E+05, Et=1.46E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=4.84E+05, Et=1.39E+07, s/n= 0.04 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.54E+05, Et=4.57E+07, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.36E+04, Et=5.85E+07, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=5.80E+05, Et=1.43E+07, s/n= 0.04 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.61E+05, Et=1.41E+07, s/n= 0.01 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=2.18E+05, Et=6.73E+07, s/n= 0.00 [Nov 1 23:59:40] DEBUG[22132] dsp.c: tone 1100, Ew=1.24E+05, Et=6.04E+07, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.40E+04, Et=5.00E+07, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=9.60E+04, Et=1.01E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=5.94E+06, Et=2.20E+08, s/n= 0.03 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.95E+07, Et=1.51E+09, s/n= 0.05 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=8.19E+07, Et=1.42E+09, s/n= 0.06 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=2.79E+06, Et=1.48E+08, s/n= 0.02 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.03E+06, Et=3.79E+08, s/n= 0.01 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.20E+05, Et=1.05E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.67E+04, Et=1.05E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.46E+05, Et=1.24E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=4.03E+04, Et=1.07E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=7.59E+06, Et=4.92E+08, s/n= 0.02 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=8.94E+07, Et=2.72E+09, s/n= 0.03 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.19E+09, Et=9.49E+09, s/n= 0.14 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=4.48E+08, Et=3.55E+09, s/n= 0.14 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=4.72E+08, Et=4.96E+09, s/n= 0.11 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.14E+08, Et=7.76E+09, s/n= 0.01 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=8.14E+07, Et=3.57E+09, s/n= 0.02 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.38E+08, Et=4.90E+09, s/n= 0.07 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=7.98E+06, Et=1.34E+09, s/n= 0.01 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.03E+06, Et=6.00E+08, s/n= 0.01 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.33E+08, Et=1.74E+09, s/n= 0.08 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=7.16E+04, Et=4.82E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=4.25E+06, Et=1.74E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=7.75E+06, Et=2.74E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=7.31E+06, Et=4.02E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.57E+05, Et=1.53E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.07E+07, Et=5.72E+08, s/n= 0.02 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=8.37E+05, Et=3.96E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.29E+06, Et=7.11E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.71E+04, Et=3.67E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=4.58E+06, Et=1.28E+08, s/n= 0.04 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.52E+08, Et=1.48E+09, s/n= 0.79 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=9.22E+08, Et=2.72E+09, s/n= 0.51 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=2.56E+09, Et=4.59E+09, s/n= 1.26 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.51E+09, Et=5.77E+09, s/n= 1.55 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=2.28E+09, Et=5.04E+09, s/n= 0.83 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=2.84E+09, Et=1.05E+10, s/n= 0.37 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.85E+09, Et=8.78E+09, s/n= 0.27 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=5.16E+07, Et=3.49E+09, s/n= 0.02 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=1.52E+08, Et=2.37E+09, s/n= 0.07 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=5.62E+06, Et=1.16E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=4.03E+05, Et=3.47E+08, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.43E+06, Et=4.89E+08, s/n= 0.01 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.84E+05, Et=1.46E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=6.16E+04, Et=2.05E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.55E+06, Et=2.05E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=2.83E+06, Et=2.26E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=9.63E+04, Et=3.07E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=3.55E+05, Et=4.26E+09, s/n= 0.00 [Nov 1 23:59:41] DEBUG[22132] dsp.c: tone 1100, Ew=2.89E+05, Et=2.19E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.04E+06, Et=1.06E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.40E+05, Et=9.20E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=6.52E+05, Et=1.15E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=6.16E+05, Et=9.03E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.81E+06, Et=7.49E+08, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.53E+05, Et=6.63E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.13E+05, Et=7.94E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.10E+05, Et=1.45E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=7.59E+05, Et=9.21E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] res_rtp_asterisk.c: Got RTCP report of 128 bytes [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.37E+05, Et=1.33E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.23E+06, Et=1.18E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=2.22E+05, Et=5.61E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.90E+05, Et=4.80E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=5.54E+05, Et=2.83E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.12E+06, Et=3.34E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.94E+06, Et=2.99E+08, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.75E+07, Et=2.92E+08, s/n= 0.06 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.52E+08, Et=3.09E+09, s/n= 0.13 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.10E+09, Et=1.48E+10, s/n= 0.26 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=2.76E+09, Et=2.76E+10, s/n= 0.11 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.45E+09, Et=1.37E+10, s/n= 0.12 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.33E+09, Et=1.23E+10, s/n= 0.12 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=8.27E+07, Et=3.63E+09, s/n= 0.02 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=9.14E+06, Et=1.42E+09, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.84E+07, Et=1.20E+09, s/n= 0.02 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.20E+07, Et=4.46E+08, s/n= 0.03 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.12E+07, Et=8.51E+08, s/n= 0.04 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=6.59E+05, Et=3.22E+08, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=2.65E+06, Et=4.45E+08, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=4.87E+06, Et=2.73E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=2.64E+07, Et=7.80E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=6.98E+06, Et=3.31E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=4.48E+06, Et=3.22E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=2.59E+07, Et=4.64E+09, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.23E+07, Et=6.79E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.67E+06, Et=8.13E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=9.85E+07, Et=9.97E+09, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=8.25E+07, Et=1.12E+10, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.25E+08, Et=9.68E+09, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=9.32E+08, Et=1.52E+10, s/n= 0.07 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.12E+08, Et=1.38E+10, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.97E+09, Et=1.36E+10, s/n= 0.17 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.07E+07, Et=4.74E+09, s/n= 0.01 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.25E+08, Et=3.03E+09, s/n= 0.04 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=8.22E+06, Et=2.09E+09, s/n= 0.00 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=9.06E+06, Et=4.20E+08, s/n= 0.02 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=4.92E+06, Et=6.77E+07, s/n= 0.08 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=1.79E+07, Et=9.09E+07, s/n= 0.25 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=3.56E+07, Et=2.40E+08, s/n= 0.17 [Nov 1 23:59:42] DEBUG[22132] dsp.c: tone 1100, Ew=2.48E+08, Et=1.28E+10, s/n= 0.02 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=4.03E+08, Et=1.24E+10, s/n= 0.03 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=5.90E+07, Et=6.44E+09, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.09E+07, Et=1.39E+10, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.44E+08, Et=2.81E+09, s/n= 0.05 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.72E+08, Et=2.28E+09, s/n= 0.08 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.76E+09, Et=7.29E+09, s/n= 0.32 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=2.66E+08, Et=3.39E+09, s/n= 0.09 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=8.33E+08, Et=2.55E+09, s/n= 0.48 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=5.15E+07, Et=2.24E+10, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=5.18E+08, Et=2.67E+10, s/n= 0.02 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=3.82E+09, Et=2.69E+10, s/n= 0.17 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=3.31E+08, Et=1.07E+10, s/n= 0.03 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.34E+08, Et=5.86E+09, s/n= 0.02 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=2.62E+08, Et=6.56E+09, s/n= 0.04 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.76E+06, Et=5.31E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=8.08E+07, Et=6.24E+09, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=2.72E+06, Et=2.57E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=5.88E+05, Et=1.00E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.71E+07, Et=2.73E+09, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=6.64E+05, Et=2.76E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=2.30E+06, Et=1.37E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=3.37E+06, Et=1.00E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=6.37E+05, Et=1.17E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.91E+05, Et=1.16E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.33E+06, Et=2.36E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=3.44E+06, Et=1.02E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=8.64E+06, Et=1.69E+08, s/n= 0.05 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=2.31E+07, Et=4.31E+09, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.61E+07, Et=4.55E+09, s/n= 0.02 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.73E+07, Et=3.19E+09, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=5.20E+07, Et=1.49E+09, s/n= 0.04 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.74E+06, Et=1.42E+08, s/n= 0.06 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.12E+06, Et=9.74E+07, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=3.24E+06, Et=8.95E+07, s/n= 0.04 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.51E+06, Et=1.03E+08, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=5.72E+05, Et=4.98E+08, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.09E+07, Et=3.87E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=6.96E+05, Et=2.90E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.72E+05, Et=5.03E+08, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=6.06E+06, Et=3.09E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.20E+07, Et=2.97E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=4.00E+07, Et=5.91E+10, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.83E+06, Et=1.55E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=9.60E+06, Et=6.02E+08, s/n= 0.02 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.28E+07, Et=3.23E+08, s/n= 0.04 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=1.05E+06, Et=1.31E+08, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=6.50E+09, Et=2.19E+11, s/n= 0.03 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.59E+08, Et=1.31E+11, s/n= 0.01 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=3.85E+06, Et=6.91E+09, s/n= 0.00 [Nov 1 23:59:43] DEBUG[22132] dsp.c: tone 1100, Ew=7.85E+06, Et=6.36E+08, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.69E+06, Et=2.79E+08, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.25E+07, Et=2.30E+08, s/n= 0.16 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=4.34E+06, Et=1.24E+08, s/n= 0.04 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.10E+06, Et=1.70E+08, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.89E+07, Et=9.12E+08, s/n= 0.02 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.39E+06, Et=4.95E+07, s/n= 0.03 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=6.67E+06, Et=1.05E+08, s/n= 0.07 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=6.98E+06, Et=6.99E+07, s/n= 0.11 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=7.91E+05, Et=7.04E+07, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.59E+06, Et=1.03E+08, s/n= 0.04 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=5.59E+06, Et=8.41E+07, s/n= 0.07 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.95E+06, Et=4.80E+07, s/n= 0.07 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.80E+05, Et=5.37E+07, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.21E+05, Et=5.24E+07, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.16E+05, Et=5.97E+07, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=4.11E+05, Et=4.28E+07, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=8.79E+05, Et=9.41E+08, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] res_rtp_asterisk.c: Got RTCP report of 128 bytes [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.64E+06, Et=3.17E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.20E+07, Et=2.07E+09, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.10E+06, Et=1.48E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=9.62E+06, Et=2.15E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.77E+05, Et=2.27E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.11E+06, Et=3.99E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.72E+07, Et=3.94E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.01E+08, Et=4.60E+09, s/n= 0.02 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.22E+08, Et=2.71E+10, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=6.07E+08, Et=8.95E+09, s/n= 0.07 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.01E+08, Et=4.13E+09, s/n= 0.02 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.06E+08, Et=1.67E+10, s/n= 0.02 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.32E+07, Et=7.32E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.29E+07, Et=6.05E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.56E+06, Et=3.89E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.17E+05, Et=4.58E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=8.79E+06, Et=1.93E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.50E+06, Et=4.65E+08, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.20E+06, Et=3.31E+08, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=7.97E+05, Et=3.57E+08, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=5.09E+06, Et=2.52E+08, s/n= 0.02 [Nov 1 23:59:44] DEBUG[22133] manager.c: Running action 'Login' [Nov 1 23:59:44] DEBUG[22133] manager.c: Running action 'Command' [Nov 1 23:59:44] DEBUG[22133] manager.c: Running action 'Logoff' [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.95E+09, Et=1.68E+10, s/n= 0.13 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=4.81E+08, Et=5.89E+09, s/n= 0.09 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=5.60E+07, Et=5.69E+09, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.31E+07, Et=2.73E+09, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=5.37E+06, Et=3.41E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.05E+08, Et=4.10E+09, s/n= 0.03 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=1.43E+07, Et=4.30E+09, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=9.63E+05, Et=3.30E+07, s/n= 0.03 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=7.76E+05, Et=3.16E+07, s/n= 0.03 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=3.65E+05, Et=3.31E+07, s/n= 0.01 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=8.05E+09, Et=1.71E+12, s/n= 0.00 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 0 [ 32]: INVITE sip:*8@example.net SIP/2.0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.1.139:3832;branch=z9hG4bK-d8754z-733ca866c7054c5a-1---d8754z-;rport [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 3 [ 34]: Contact: [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 4 [ 27]: To: "*8" [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 5 [ 49]: From: "139@home";tag=d66b8a60 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 6 [ 53]: Call-ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 7 [ 14]: CSeq: 1 INVITE [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 10 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 11 [ 19]: Content-Length: 307 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 12 [ 0]: [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 0 [ 3]: v=0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 1 [ 25]: o=- 3 2 IN IP4 192.168.1.139 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 2 [ 25]: s=CounterPath eyeBeam 1.5 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 3 [ 19]: c=IN IP4 192.168.1.139 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 5 [ 36]: m=audio 16196 RTP/AVP 107 0 8 18 111 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 6 [ 46]: a=alt:1 1 : dr24xnCD JK/qEbAE 192.168.1.139 16196 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 7 [ 20]: a=fmtp:18 annexb=yes [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 8 [ 15]: a=fmtp:111 0-15 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 9 [ 23]: a=rtpmap:107 BV32/16000 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 10 [ 21]: a=rtpmap:18 G729/8000 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 11 [ 33]: a=rtpmap:111 telephone-event/8000 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 12 [ 10]: a=sendrecv [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: = Looking for Call ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. (Checking From) --From tag d66b8a60 --To-tag [Nov 1 23:59:44] DEBUG[7866] acl.c: For destination '192.168.1.139', our source address is '192.168.1.10'. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.10:5060 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Allocating new SIP dialog for MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. - INVITE (No RTP) [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting '192.168.1.139:3832' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host '192.168.1.139' and port '3832'. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Initializing initreq for method INVITE - callid MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting 'example.net' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host 'example.net' and port ''. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137598 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.139:3832 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 0 [ 29]: ACK sip:*8@example.net SIP/2.0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.1.139:3832;branch=z9hG4bK-d8754z-733ca866c7054c5a-1---d8754z-;rport [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 2 [ 42]: To: "*8";tag=as741befcf [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 3 [ 49]: From: "139@home";tag=d66b8a60 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 4 [ 53]: Call-ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 5 [ 11]: CSeq: 1 ACK [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: = Looking for Call ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. (Checking From) --From tag d66b8a60 --To-tag as741befcf [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137598 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Stopping retransmission on 'MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q.' of Response 1: Match Found [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 0 [ 32]: INVITE sip:*8@example.net SIP/2.0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.1.139:3832;branch=z9hG4bK-d8754z-22661552532db11d-1---d8754z-;rport [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 3 [ 34]: Contact: [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 4 [ 27]: To: "*8" [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 5 [ 49]: From: "139@home";tag=d66b8a60 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 6 [ 53]: Call-ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 7 [ 14]: CSeq: 2 INVITE [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 10 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 11 [152]: Authorization: Digest username="139",realm="asterisk",nonce="523d7085",uri="sip:*8@example.net",response="2d6d42372fc83195a698ac60020aac6f",algorithm=MD5 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 12 [ 19]: Content-Length: 307 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Header 13 [ 0]: [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 0 [ 3]: v=0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 1 [ 25]: o=- 3 2 IN IP4 192.168.1.139 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 2 [ 25]: s=CounterPath eyeBeam 1.5 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 3 [ 19]: c=IN IP4 192.168.1.139 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 5 [ 36]: m=audio 16196 RTP/AVP 107 0 8 18 111 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 6 [ 46]: a=alt:1 1 : dr24xnCD JK/qEbAE 192.168.1.139 16196 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 7 [ 20]: a=fmtp:18 annexb=yes [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 8 [ 15]: a=fmtp:111 0-15 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 9 [ 23]: a=rtpmap:107 BV32/16000 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 10 [ 21]: a=rtpmap:18 G729/8000 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 11 [ 33]: a=rtpmap:111 telephone-event/8000 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Body 12 [ 10]: a=sendrecv [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: = Looking for Call ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. (Checking From) --From tag d66b8a60 --To-tag [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting 'example.net' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host 'example.net' and port ''. [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting 'example.net' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host 'example.net' and port ''. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting '192.168.1.139:3832' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host '192.168.1.139' and port '3832'. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Initializing initreq for method INVITE - callid MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting 'example.net' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host 'example.net' and port ''. [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x923d220' [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Allocated port 10070 for RTP instance '0x923d220' [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: RTP instance '0x923d220' is setup and ready to go [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x92403f0' [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Allocated port 10068 for RTP instance '0x92403f0' [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: RTP instance '0x92403f0' is setup and ready to go [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x92403f0' [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x923d220' [Nov 1 23:59:44] VERBOSE[7866] netsock2.c: == Using SIP RTP CoS mark 5 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Setting NAT on RTP to On [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Setting NAT on VRTP to On [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing session-level SDP o=- 3 2 IN IP4 192.168.1.139... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing session-level SDP s=CounterPath eyeBeam 1.5... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting '192.168.1.139' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host '192.168.1.139' and port ''. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.139... OK. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Setting payload 0 based on m type on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Setting payload 8 based on m type on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Setting payload 18 based on m type on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Setting payload 111 based on m type on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=alt:1 1 : dr24xnCD JK/qEbAE 192.168.1.139 16196... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=yes... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 0-15... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Unsetting payload 107 on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 BV32/16000... UNSUPPORTED OR FAILED. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 telephone-event/8000... OK. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Incorporating payload 0 on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Incorporating payload 8 on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Incorporating payload 18 on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Incorporating payload 111 on 0xb638f3b4 [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x923d220' [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Copying payload 0 from 0xb638f3b4 to 0x923d3cc [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Copying payload 8 from 0xb638f3b4 to 0x923d3cc [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Copying payload 18 from 0xb638f3b4 to 0x923d3cc [Nov 1 23:59:44] DEBUG[7866] rtp_engine.c: Copying payload 111 from 0xb638f3b4 to 0x923d3cc [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x923d220' [Nov 1 23:59:44] DEBUG[7866] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x92403f0' [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Checking SIP call limits for device 139 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Updating call counter for incoming call [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting 'example.net' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host 'example.net' and port ''. [Nov 1 23:59:44] DEBUG[7866] netsock2.c: Splitting 'example.net' into... [Nov 1 23:59:44] DEBUG[7866] netsock2.c: ...host 'example.net' and port ''. [Nov 1 23:59:44] DEBUG[7881] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/139-0000020b ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 139 CallerIDName: testing AccountCode: Exten: *8 Context: extensions Uniqueid: 1351828784.682 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: *** Our capabilities are 0x280404 (ulaw|ilbc|h263|h264) [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Nov 1 23:59:44] DEBUG[7866] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 1 23:59:44] DEBUG[7866] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: build_route: Contact hop: [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Session timer started: 137600 - MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: SIP/139-0000020b: New call is still down.... Trying... [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.139:3832 [Nov 1 23:59:44] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 139 [Nov 1 23:59:44] DEBUG[7881] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/139-0000020b ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 139 CallerIDName: testing ConnectedLineNum: ConnectedLineName: Uniqueid: 1351828784.682 [Nov 1 23:59:44] DEBUG[7855] chan_sip.c: Checking device state for peer 139 [Nov 1 23:59:44] DEBUG[7855] devicestate.c: Changing state for SIP/139 - state 1 (Not in use) [Nov 1 23:59:44] DEBUG[7855] devicestate.c: device 'SIP/139' state '1' [Nov 1 23:59:44] DEBUG[7866] chan_sip.c: Started Group pickup thread on channel SIP/139-0000020b [Nov 1 23:59:44] DEBUG[22134] features.c: pickup attempt by SIP/139-0000020b [Nov 1 23:59:44] NOTICE[22134] features.c: pickup SIP/111-00000209 attempt by SIP/139-0000020b [Nov 1 23:59:44] DEBUG[22134] features.c: Call pickup on 'SIP/111-00000209' by 'SIP/139-0000020b' [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: SIP answering channel: SIP/139-0000020b [Nov 1 23:59:44] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 139 [Nov 1 23:59:44] DEBUG[22134] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:44] DEBUG[7855] chan_sip.c: Checking device state for peer 139 [Nov 1 23:59:44] DEBUG[7855] devicestate.c: Changing state for SIP/139 - state 1 (Not in use) [Nov 1 23:59:44] DEBUG[7881] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/139-0000020b ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 139 CallerIDName: testing ConnectedLineNum: 6105551111 ConnectedLineName: Jeremy Cell Uniqueid: 1351828784.682 [Nov 1 23:59:44] DEBUG[7855] devicestate.c: device 'SIP/139' state '1' [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: Setting framing from config on incoming call [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: -- Done with adding codecs to SDP [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137602 [Nov 1 23:59:44] DEBUG[22134] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.139:3832 [Nov 1 23:59:44] DEBUG[22132] dsp.c: tone 1100, Ew=2.79E+09, Et=8.76E+11, s/n= 0.00 [Nov 1 23:59:44] DEBUG[22134] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=6.84E+08, Et=5.18E+11, s/n= 0.00 [Nov 1 23:59:45] DEBUG[22134] dsp.c: tone 1100, Ew=8.12E+05, Et=8.70E+07, s/n= 0.01 [Nov 1 23:59:45] DEBUG[22134] channel.c: Planning to masquerade channel SIP/139-0000020b into the structure of SIP/111-00000209 [Nov 1 23:59:45] DEBUG[22134] channel.c: Done planning to masquerade channel SIP/139-0000020b into the structure of SIP/111-00000209 [Nov 1 23:59:45] DEBUG[22132] channel.c: Actually Masquerading SIP/139-0000020b(6) into the structure of SIP/111-00000209(5) [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Masquerade Privilege: call,all Clone: SIP/139-0000020b CloneState: Up Original: SIP/111-00000209 OriginalState: Ringing [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/139-0000020b Newname: SIP/139-0000020b Uniqueid: 1351828784.682 [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/111-00000209 Newname: SIP/139-0000020b Uniqueid: 1351828778.680 [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Pickup Privilege: call,all Channel: SIP/139-0000020b TargetChannel: SIP/111-00000209 [Nov 1 23:59:45] DEBUG[22132] channel.c: Putting channel SIP/139-0000020b in ulaw/ulaw formats [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: SIP Fixup: New owner for dialogue MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q.: SIP/139-0000020b (Old parent: SIP/111-00000209) [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: SIP Fixup: New owner for dialogue 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060: SIP/111-00000209 (Old parent: SIP/139-0000020b) [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: This call was answered elsewhere [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Hangup call SIP/111-00000209, SIP callid 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Hanging up channel in state Ringing (not UP) [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x922fd48' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Strict routing enforced for session 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Rename Privilege: call,all Channel: SIP/139-0000020b Newname: SIP/111-00000209 Uniqueid: 1351828784.682 [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/139-0000020b CallerIDNum: 139 CallerIDName: testing Uniqueid: 1351828778.680 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137605 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for 192.168.1.111:5060 [Nov 1 23:59:45] DEBUG[22132] channel.c: Done Masquerading SIP/139-0000020b (6) [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Nov 1 23:59:45] VERBOSE[22132] app_dial.c: -- SIP/139-0000020b answered SIP/vgw1-00000208 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Strict routing enforced for session 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[22132] netsock2.c: Splitting '192.168.1.7:5060' into... [Nov 1 23:59:45] DEBUG[22132] netsock2.c: ...host '192.168.1.7' and port '5060'. [Nov 1 23:59:45] DEBUG[22134] channel.c: Hanging up zombie 'SIP/111-00000209' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/111-00000209 Uniqueid: 1351828784.682 CallerIDNum: 111 CallerIDName: Jeremy Office ConnectedLineNum: 6105551111 ConnectedLineName: Jeremy Cell Cause: 16 Cause-txt: Normal Clearing [Nov 1 23:59:45] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 1 23:59:45] DEBUG[7855] chan_sip.c: Checking device state for peer 111 [Nov 1 23:59:45] DEBUG[7855] devicestate.c: Changing state for SIP/111 - state 1 (Not in use) [Nov 1 23:59:45] DEBUG[7855] devicestate.c: device 'SIP/111' state '1' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: -- Done with adding codecs to SDP [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Initializing already initialized SIP dialog 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 (presumably reinvite) [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 0 [ 44]: INVITE sip:16105551111@192.168.1.7:5060 SIP/2.0 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK3b04a562;rport [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 3 [ 46]: From: ;tag=as6e1fb859 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 4 [ 66]: To: "WIRELESS CALLER" ;tag=1B3646CB-229E [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 5 [ 39]: Contact: [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 6 [ 52]: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 10 [ 19]: Supported: replaces [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 11 [ 86]: Remote-Party-ID: "Jeremy Office" ;party=called;privacy=off;screen=no [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137607 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.7:62151 [Nov 1 23:59:45] DEBUG[22132] channel.c: Hanging up channel 'SIP/112-0000020a' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: This call was answered elsewhere [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: ####### It's the cause code, buddy. The cause code!!! [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Hangup call SIP/112-0000020a, SIP callid 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Hanging up channel in state Ringing (not UP) [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x922e750' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '541c001e3392734f67235180750a0423@192.168.1.10:5060' Request 102: Found [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Strict routing enforced for session 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137609 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for 192.168.1.112:5060 [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/112-0000020a Uniqueid: 1351828778.681 CallerIDNum: 112 CallerIDName: Great Rm ConnectedLineNum: 6105551111 ConnectedLineName: Jeremy Cell Cause: 26 Cause-txt: Unknown [Nov 1 23:59:45] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 112 [Nov 1 23:59:45] DEBUG[7855] chan_sip.c: Checking device state for peer 112 [Nov 1 23:59:45] DEBUG[7855] devicestate.c: Changing state for SIP/112 - state 1 (Not in use) [Nov 1 23:59:45] DEBUG[7855] devicestate.c: device 'SIP/112' state '1' [Nov 1 23:59:45] DEBUG[22132] channel.c: Set channel SIP/vgw1-00000208 to write format ulaw [Nov 1 23:59:45] DEBUG[22132] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: NewAccountCode Privilege: call,all Channel: SIP/139-0000020b Uniqueid: 1351828778.680 AccountCode: OldAccountCode: [Nov 1 23:59:45] DEBUG[22132] features.c: bridge answer set, chan answer set [Nov 1 23:59:45] DEBUG[22132] features.c: Removing dialed interfaces datastore on SIP/139-0000020b since we're bridging [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Bridge Privilege: call,all Bridgestate: Link Bridgetype: core Channel1: SIP/vgw1-00000208 Channel2: SIP/139-0000020b Uniqueid1: 1351828778.679 Uniqueid2: 1351828778.680 CallerID1: 6105551111 CallerID2: 139 [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=1.61E+09, Et=8.54E+11, s/n= 0.00 [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Nov 1 23:59:45] DEBUG[22132] channel.c: Dropping duplicate answer! [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Strict routing enforced for session 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[22132] netsock2.c: Splitting '192.168.1.7:5060' into... [Nov 1 23:59:45] DEBUG[22132] netsock2.c: ...host '192.168.1.7' and port '5060'. [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137611 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Trying to put 'UPDATE sip:' onto UDP socket destined for 192.168.1.7:62151 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=5.85E+05, Et=6.72E+07, s/n= 0.01 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=1.22E+09, Et=8.65E+11, s/n= 0.00 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: <--- SIP read from UDP:192.168.1.7:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK3b04a562;rport From: ;tag=as6e1fb859 To: "WIRELESS CALLER" ;tag=1B3646CB-229E Date: Fri, 02 Nov 2012 04:06:02 GMT Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Remote-Party-ID: "WIRELESS CALLER" ;party=called;screen=no;privacy=off Content-Length: 0 <-------------> [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK3b04a562;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 46]: From: ;tag=as6e1fb859 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 66]: To: "WIRELESS CALLER" ;tag=1B3646CB-229E [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 35]: Date: Fri, 02 Nov 2012 04:06:02 GMT [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 52]: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 29]: Allow-Events: telephone-event [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 9 [ 96]: Remote-Party-ID: "WIRELESS CALLER" ;party=called;screen=no;privacy=off [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: --- (11 headers 0 lines) --- [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 (Checking To) --From tag as6e1fb859 --To-tag 1B3646CB-229E [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: *** SIP TIMER: Cancelling retransmission #137607 - INVITE (got response) [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7' Request 102: Found [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: SIP response 100 to RE-invite on outgoing call 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: <--- SIP read from UDP:192.168.1.7:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK3b04a562;rport From: ;tag=as6e1fb859 To: "WIRELESS CALLER" ;tag=1B3646CB-229E Date: Fri, 02 Nov 2012 04:06:02 GMT Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Supported: replaces Allow-Events: telephone-event Remote-Party-ID: "WIRELESS CALLER" ;party=called;screen=no;privacy=off Contact: Content-Type: application/sdp Content-Length: 235 v=0 o=CiscoSystemsSIP-GW-UserAgent 4498 9213 IN IP4 192.168.1.7 s=SIP Call c=IN IP4 192.168.1.7 t=0 0 m=audio 16674 RTP/AVP 0 111 c=IN IP4 192.168.1.7 a=rtpmap:0 PCMU/8000 a=rtpmap:111 telephone-event/8000 a=fmtp:111 0-16 a=ptime:20 <-------------> [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK3b04a562;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 46]: From: ;tag=as6e1fb859 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 66]: To: "WIRELESS CALLER" ;tag=1B3646CB-229E [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 35]: Date: Fri, 02 Nov 2012 04:06:02 GMT [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 52]: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [112]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 9 [ 19]: Supported: replaces [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 10 [ 29]: Allow-Events: telephone-event [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 11 [ 96]: Remote-Party-ID: "WIRELESS CALLER" ;party=called;screen=no;privacy=off [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 12 [ 40]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 14 [ 19]: Content-Length: 235 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 15 [ 0]: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 0 [ 3]: v=0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 1 [ 56]: o=CiscoSystemsSIP-GW-UserAgent 4498 9213 IN IP4 192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 2 [ 10]: s=SIP Call [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 3 [ 17]: c=IN IP4 192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 5 [ 27]: m=audio 16674 RTP/AVP 0 111 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 6 [ 17]: c=IN IP4 192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 8 [ 33]: a=rtpmap:111 telephone-event/8000 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 9 [ 15]: a=fmtp:111 0-16 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: --- (15 headers 11 lines) --- [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 (Checking To) --From tag as6e1fb859 --To-tag 1B3646CB-229E [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Acked pending invite 102 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on '6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7' of Request 102: Match Found [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: SIP response 200 to RE-invite on outgoing call 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Call 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 responded to our reinvite without changing SDP version; ignoring SDP. [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Updating call counter for incoming call [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Strict routing enforced for session 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: set_destination: Parsing for address/port to send to [Nov 1 23:59:45] DEBUG[7866] netsock2.c: Splitting '192.168.1.7:5060' into... [Nov 1 23:59:45] DEBUG[7866] netsock2.c: ...host '192.168.1.7' and port '5060'. [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: set_destination: set destination to 192.168.1.7:5060 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: Transmitting (NAT) to 192.168.1.7:5060: ACK sip:16105551111@192.168.1.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK25bde6a5;rport Max-Forwards: 70 From: ;tag=as6e1fb859 To: "WIRELESS CALLER" ;tag=1B3646CB-229E Contact: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.15.0 Content-Length: 0 --- [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Trying to put 'ACK sip:126' onto UDP socket destined for 192.168.1.7:5060 [Nov 1 23:59:45] DEBUG[22132] channel.c: Got a FRAME_CONTROL (31) frame on channel SIP/vgw1-00000208 [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Unlink Privilege: call,all Channel1: SIP/vgw1-00000208 Channel2: SIP/139-0000020b Uniqueid1: 1351828778.679 Uniqueid2: 1351828778.680 CallerID1: 6105551111 CallerID2: 139 [Nov 1 23:59:45] DEBUG[22132] channel.c: Bridge stops bridging channels SIP/vgw1-00000208 and SIP/139-0000020b [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Bridge Privilege: call,all Bridgestate: Link Bridgetype: core Channel1: SIP/vgw1-00000208 Channel2: SIP/139-0000020b Uniqueid1: 1351828778.679 Uniqueid2: 1351828778.680 CallerID1: 6105551111 CallerID2: 139 [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=1.08E+05, Et=3.41E+07, s/n= 0.00 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK593bd998;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as21490600 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 24]: To: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 16]: CSeq: 102 CANCEL [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 55]: Call-ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 29]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/3.1.6.0017 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 (Checking To) --From tag as21490600 --To-tag [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Acked pending invite 102 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137605 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on '4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060' of Request 102: Match Found [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=6.98E+08, Et=2.56E+10, s/n= 0.03 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=1.43E+05, Et=2.11E+07, s/n= 0.01 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=2.01E+07, Et=4.63E+09, s/n= 0.00 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 32]: ACK sip:*8@192.168.1.10:5060 SIP/2.0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.1.139:3832;branch=z9hG4bK-d8754z-9a12be65d61fb217-1---d8754z-;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 34]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 42]: To: "*8";tag=as44299b62 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 49]: From: "139@home";tag=d66b8a60 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 53]: Call-ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 11]: CSeq: 2 ACK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 9 [152]: Authorization: Digest username="139",realm="asterisk",nonce="523d7085",uri="sip:*8@example.net",response="2d6d42372fc83195a698ac60020aac6f",algorithm=MD5 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. (Checking From) --From tag d66b8a60 --To-tag as44299b62 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137602 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on 'MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q.' of Response 2: Match Found [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 29]: SIP/2.0 487 Request Cancelled [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK593bd998;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as21490600 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 46]: To: ;tag=4FDF88CB-F853091C [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 55]: Call-ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 29]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/3.1.6.0017 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 (Checking To) --From tag as21490600 --To-tag 4FDF88CB-F853091C [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on '4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060' of Request 102: Match Found [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: SIP response 487 to standard invite [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Strict routing enforced for session 4a6f0ced71674b632418e2b3734d8555@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Trying to put 'ACK sip:111' onto UDP socket destined for 192.168.1.111:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Updating call counter for outgoing call [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=2.89E+05, Et=3.23E+07, s/n= 0.01 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=2.61E+07, Et=2.29E+09, s/n= 0.01 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=1.44E+05, Et=5.41E+07, s/n= 0.00 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK4f64e6f1;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as4c33f92c [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 81]: To: ;tag=0013c401d7df384b16efc379-1544e634 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 55]: Call-ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 35]: Date: Fri, 02 Nov 2012 04:08:17 GMT [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 16]: CSeq: 102 CANCEL [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 25]: Server: Cisco-CP7940G/8.0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 (Checking To) --From tag as4c33f92c --To-tag 0013c401d7df384b16efc379-1544e634 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Acked pending invite 102 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137609 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on '541c001e3392734f67235180750a0423@192.168.1.10:5060' of Request 102: Match Found [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=6.07E+05, Et=3.10E+07, s/n= 0.02 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: SIP TIMER: Rescheduling retransmission #137611 (1) UPDATE - 12 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #137611)) [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: Retransmitting #1 (NAT) to 192.168.1.7:5060: UPDATE sip:16105551111@192.168.1.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK1eeea495;rport Max-Forwards: 70 From: ;tag=as6e1fb859 To: "WIRELESS CALLER" ;tag=1B3646CB-229E Contact: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 CSeq: 103 UPDATE User-Agent: Asterisk PBX 1.8.15.0 Remote-Party-ID: "testing" ;party=calling;privacy=off;screen=no X-Asterisk-rpid-update: Yes Content-Length: 0 --- [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Trying to put 'UPDATE sip:' onto UDP socket destined for 192.168.1.7:5060 [Nov 1 23:59:45] DEBUG[22132] dsp.c: tone 1100, Ew=1.49E+05, Et=2.29E+07, s/n= 0.01 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: <--- SIP read from UDP:192.168.1.7:5060 ---> SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK1eeea495;rport From: ;tag=as6e1fb859 To: "WIRELESS CALLER" ;tag=1B3646CB-229E Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 CSeq: 103 UPDATE Content-Length: 0 <-------------> [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 33]: SIP/2.0 500 Internal Server Error [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK1eeea495;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 46]: From: ;tag=as6e1fb859 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 66]: To: "WIRELESS CALLER" ;tag=1B3646CB-229E [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 52]: Call-ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 16]: CSeq: 103 UPDATE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: --- (7 headers 0 lines) --- [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 (Checking To) --From tag as6e1fb859 --To-tag 1B3646CB-229E [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137611 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on '6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7' of Request 103: Match Found [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: -- Got SIP response 500 "Internal Server Error" back from 192.168.1.7:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[22132] channel.c: Got a FRAME_CONTROL (8) frame on channel SIP/vgw1-00000208 [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Unlink Privilege: call,all Channel1: SIP/vgw1-00000208 Channel2: SIP/139-0000020b Uniqueid1: 1351828778.679 Uniqueid2: 1351828778.680 CallerID1: 6105551111 CallerID2: 139 [Nov 1 23:59:45] DEBUG[22132] channel.c: Bridge stops bridging channels SIP/vgw1-00000208 and SIP/139-0000020b [Nov 1 23:59:45] DEBUG[22132] channel.c: Hanging up channel 'SIP/139-0000020b' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Hangup call SIP/139-0000020b, SIP callid MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x923d220' [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x92403f0' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Session timer stopped: 137600 - MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Strict routing enforced for session MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[22132] netsock2.c: Splitting '192.168.1.139:3832' into... [Nov 1 23:59:45] DEBUG[22132] netsock2.c: ...host '192.168.1.139' and port '3832'. [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #137614 [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Trying to put 'BYE sip:139' onto UDP socket destined for 192.168.1.139:3832 [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/139-0000020b Uniqueid: 1351828778.680 CallerIDNum: 139 CallerIDName: testing ConnectedLineNum: 6105551111 ConnectedLineName: Jeremy Cell Cause: 16 Cause-txt: Normal Clearing [Nov 1 23:59:45] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - 139 [Nov 1 23:59:45] DEBUG[7855] chan_sip.c: Checking device state for peer 139 [Nov 1 23:59:45] DEBUG[7855] devicestate.c: Changing state for SIP/139 - state 1 (Not in use) [Nov 1 23:59:45] DEBUG[7855] devicestate.c: device 'SIP/139' state '1' [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: End Channel: SIP/vgw1-00000208 UniqueID: 1351828778.679 DialStatus: ANSWER [Nov 1 23:59:45] DEBUG[22132] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Nov 1 23:59:45] DEBUG[22132] pbx.c: Spawn extension (attendant,s,2) exited non-zero on 'SIP/vgw1-00000208' [Nov 1 23:59:45] VERBOSE[22132] pbx.c: == Spawn extension (attendant, s, 2) exited non-zero on 'SIP/vgw1-00000208' [Nov 1 23:59:45] DEBUG[22132] channel.c: Soft-Hanging up channel 'SIP/vgw1-00000208' [Nov 1 23:59:45] DEBUG[22132] channel.c: Hanging up channel 'SIP/vgw1-00000208' [Nov 1 23:59:45] DEBUG[22132] chan_sip.c: Hangup call SIP/vgw1-00000208, SIP callid 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] DEBUG[22132] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6233150' [Nov 1 23:59:45] DEBUG[7881] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/vgw1-00000208 Uniqueid: 1351828778.679 CallerIDNum: 6105551111 CallerIDName: Jeremy Cell ConnectedLineNum: 139 ConnectedLineName: testing Cause: 16 Cause-txt: Normal Clearing [Nov 1 23:59:45] DEBUG[7855] devicestate.c: No provider found, checking channel drivers for SIP - vgw1 [Nov 1 23:59:45] DEBUG[7855] chan_sip.c: Checking device state for peer vgw1 [Nov 1 23:59:45] DEBUG[7855] devicestate.c: Changing state for SIP/vgw1 - state 1 (Not in use) [Nov 1 23:59:45] DEBUG[7855] devicestate.c: device 'SIP/vgw1' state '1' [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 29]: SIP/2.0 487 Request Cancelled [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK4f64e6f1;rport [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 60]: From: "Jeremy Cell" ;tag=as4c33f92c [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 81]: To: ;tag=0013c401d7df384b16efc379-1544e634 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 55]: Call-ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 35]: Date: Fri, 02 Nov 2012 04:08:17 GMT [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 25]: Server: Cisco-CP7940G/8.0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 48]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 9 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: 541c001e3392734f67235180750a0423@192.168.1.10:5060 (Checking To) --From tag as4c33f92c --To-tag 0013c401d7df384b16efc379-1544e634 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on '541c001e3392734f67235180750a0423@192.168.1.10:5060' of Request 102: Match Found [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: SIP response 487 to standard invite [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Strict routing enforced for session 541c001e3392734f67235180750a0423@192.168.1.10:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Trying to put 'ACK sip:112' onto UDP socket destined for 192.168.1.112:5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Updating call counter for outgoing call [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Destroying SIP dialog 6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7 [Nov 1 23:59:45] VERBOSE[7866] chan_sip.c: Really destroying SIP dialog '6F6DDA2A-23D911E2-8F9795E0-779A0B0@192.168.1.7' Method: ACK [Nov 1 23:59:45] DEBUG[7866] rtp_engine.c: Destroyed RTP instance '0xb6233150' [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: SIP TIMER: Rescheduling retransmission #137614 (1) BYE - 8 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 218 ms (t1 109 ms (Retrans id #137614)) [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Trying to put 'BYE sip:139' onto UDP socket destined for 192.168.1.139:3832 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK39263b9e;rport=5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 34]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 47]: To: "139@home";tag=d66b8a60 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 44]: From: "*8";tag=as44299b62 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 53]: Call-ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 13]: CSeq: 102 BYE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. (Checking To) --From tag as44299b62 --To-tag d66b8a60 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137614 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Stopping retransmission on 'MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q.' of Request 102: Match Found [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Destroying SIP dialog MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[7866] rtp_engine.c: Destroyed RTP instance '0x923d220' [Nov 1 23:59:45] DEBUG[7866] rtp_engine.c: Destroyed RTP instance '0x92403f0' [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK39263b9e;rport=5060 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 2 [ 34]: Contact: [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 3 [ 47]: To: "139@home";tag=d66b8a60 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 4 [ 44]: From: "*8";tag=as44299b62 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 5 [ 53]: Call-ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 6 [ 13]: CSeq: 102 BYE [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 7 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: = Looking for Call ID: MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. (Checking To) --From tag as44299b62 --To-tag d66b8a60 [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: That's odd... Got a response on a call we don't know about. Callid MzcyZGZhMDI0Mjk5MmFiNGJhODc1NjVjNjUyYTIzN2Q. [Nov 1 23:59:45] DEBUG[7866] chan_sip.c: Invalid SIP message - rejected , no callid, len 340