[Jun 3 15:33:04] VERBOSE[2822] logger.c: -- Accepting call from '6053356100' to '9733760991' on channel 3/16, span 1 [Jun 3 15:33:04] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 112 [Jun 3 15:33:04] DEBUG[1476] pbx.c: Launching 'Macro' [Jun 3 15:33:04] VERBOSE[1476] logger.c: -- Executing [9733760991@default:1] Macro("Zap/112-1", "MTTDial|SIP/9733760991@fsa-mg2") in new stack [Jun 3 15:33:04] DEBUG[1476] pbx.c: Launching 'Dial' [Jun 3 15:33:04] VERBOSE[1476] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/112-1", "SIP/9733760991@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:04] DEBUG[1476] rtp.c: Channel 'Zap/112-1' has no RTP, not doing anything [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable ARG1. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable ANI2. [Jun 3 15:33:04] DEBUG[1476] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Outgoing Call for 9733760991 [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[1476] logger.c: Audio is at 64.19.145.7 port 14374 [Jun 3 15:33:04] VERBOSE[1476] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:04] DEBUG[1476] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[1476] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9733760991@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK31647e25;rport^M From: "6053356100" ;tag=as547ae42e^M To: ^M Contact: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:04 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 14374 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:04] VERBOSE[1476] logger.c: -- Called 9733760991@fsa-mg2 [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK31647e25;received=64.19.145.7;rport=5060^M From: "6053356100" ;tag=as547ae42e^M To: ;tag=as5623c4e7^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4953cf95"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Stopping retransmission on '573fabda55a14b1119085740373ef29f@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:04] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733760991@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK31647e25;rport^M From: "6053356100" ;tag=as547ae42e^M To: ;tag=as5623c4e7^M Contact: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 14374 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9733760991@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK4054cfdf;rport^M From: "6053356100" ;tag=as547ae42e^M To: ^M Contact: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:9733760991@64.19.145.4", nonce="4953cf95", response="d383cc79b61ed5b29f815d80ef1370da"^M Date: Tue, 03 Jun 2008 19:33:04 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 14374 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:04] DEBUG[1148] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK4054cfdf;received=64.19.145.7;rport=5060^M From: "6053356100" ;tag=as547ae42e^M To: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '573fabda55a14b1119085740373ef29f@64.19.145.7' Request 103: Found [Jun 3 15:33:04] DEBUG[1193] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:04] VERBOSE[2822] logger.c: -- Accepting call from '9733953226' to '2017849880' on channel 3/17, span 1 [Jun 3 15:33:04] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 113 [Jun 3 15:33:04] DEBUG[1477] pbx.c: Launching 'Macro' [Jun 3 15:33:04] VERBOSE[1477] logger.c: -- Executing [2017849880@default:1] Macro("Zap/113-1", "MTTDial|SIP/2017849880@fsa-mg2") in new stack [Jun 3 15:33:04] DEBUG[1477] pbx.c: Launching 'Dial' [Jun 3 15:33:04] VERBOSE[1477] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/113-1", "SIP/2017849880@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:04] DEBUG[1477] rtp.c: Channel 'Zap/113-1' has no RTP, not doing anything [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable ARG1. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable ANI2. [Jun 3 15:33:04] DEBUG[1477] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Outgoing Call for 2017849880 [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[1477] logger.c: Audio is at 64.19.145.7 port 16616 [Jun 3 15:33:04] VERBOSE[1477] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:04] DEBUG[1477] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[1466] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 64.19.145.4:10803 [Jun 3 15:33:04] DEBUG[1466] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:04] VERBOSE[1477] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:2017849880@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK043c7eb5;rport^M From: "9733953226" ;tag=as6ced9960^M To: ^M Contact: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:04 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 16616 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:04] VERBOSE[1477] logger.c: -- Called 2017849880@fsa-mg2 [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK043c7eb5;received=64.19.145.7;rport=5060^M From: "9733953226" ;tag=as6ced9960^M To: ;tag=as28c67a9c^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7eaa233d"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Stopping retransmission on '098a79882bcf4927036b426a2503e8ce@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:04] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:2017849880@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK043c7eb5;rport^M From: "9733953226" ;tag=as6ced9960^M To: ;tag=as28c67a9c^M Contact: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 16616 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:2017849880@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1ff8825c;rport^M From: "9733953226" ;tag=as6ced9960^M To: ^M Contact: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:2017849880@64.19.145.4", nonce="7eaa233d", response="ae8fb219371ab0f9cccb95aa6490af0b"^M Date: Tue, 03 Jun 2008 19:33:04 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 16616 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1ff8825c;received=64.19.145.7;rport=5060^M From: "9733953226" ;tag=as6ced9960^M To: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '098a79882bcf4927036b426a2503e8ce@64.19.145.7' Request 103: Found [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK4054cfdf;received=64.19.145.7;rport=5060^M From: "6053356100" ;tag=as547ae42e^M To: ;tag=as411d0d58^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '573fabda55a14b1119085740373ef29f@64.19.145.7' Request 103: Found [Jun 3 15:33:04] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-090c81d8 [Jun 3 15:33:04] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:04] VERBOSE[1476] logger.c: -- SIP/fsa-mg2-090c81d8 is ringing [Jun 3 15:33:04] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-090c81d8 [Jun 3 15:33:04] DEBUG[1476] rtp.c: Channel 'Zap/112-1' has no RTP, not doing anything [Jun 3 15:33:04] DEBUG[1476] chan_zap.c: Requested indication 3 on channel Zap/112-1 [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-090c81d8 - state 4 (Invalid) [Jun 3 15:33:04] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:04] DEBUG[1476] devicestate.c: Notification of state change to be queued on device/channel Zap/112-1 [Jun 3 15:33:04] DEBUG[1476] devicestate.c: Notification of state change to be queued on device/channel Zap/112 [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for Zap/112-1 - state 0 (Unknown) [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for Zap/112 - state 6 (Ringing) [Jun 3 15:33:04] DEBUG[1460] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:04] DEBUG[1180] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1ff8825c;received=64.19.145.7;rport=5060^M From: "9733953226" ;tag=as6ced9960^M To: ;tag=as49a1789e^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '098a79882bcf4927036b426a2503e8ce@64.19.145.7' Request 103: Found [Jun 3 15:33:04] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08f77900 [Jun 3 15:33:04] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:04] VERBOSE[1477] logger.c: -- SIP/fsa-mg2-08f77900 is ringing [Jun 3 15:33:04] DEBUG[1477] rtp.c: Channel 'Zap/113-1' has no RTP, not doing anything [Jun 3 15:33:04] DEBUG[1477] chan_zap.c: Requested indication 3 on channel Zap/113-1 [Jun 3 15:33:04] DEBUG[1477] devicestate.c: Notification of state change to be queued on device/channel Zap/113-1 [Jun 3 15:33:04] DEBUG[1477] devicestate.c: Notification of state change to be queued on device/channel Zap/113 [Jun 3 15:33:04] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08f77900 [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08f77900 - state 4 (Invalid) [Jun 3 15:33:04] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for Zap/113-1 - state 0 (Unknown) [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for Zap/113 - state 6 (Ringing) [Jun 3 15:33:04] DEBUG[1011] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:04] DEBUG[599] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:6038681300@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK275995b4;rport^M From: ;tag=as1bce2215^M To: "6038681300" ;tag=as7d67c2e8^M Contact: ^M Call-ID: 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25458 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 10106 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:04] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:10106 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-091da298 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:10106 [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7 [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-091da298: This call is UP.... [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK275995b4;received=64.19.145.4;rport=5060^M From: ;tag=as1bce2215^M To: "6038681300" ;tag=as7d67c2e8^M Call-ID: 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 16758 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK275995b4;received=64.19.145.4;rport=5060^M From: ;tag=as1bce2215^M To: "6038681300" ;tag=as7d67c2e8^M Call-ID: 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2760 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 16758 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:6038681300@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4400de18;rport^M From: ;tag=as1bce2215^M To: "6038681300" ;tag=as7d67c2e8^M Contact: ^M Call-ID: 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Stopping retransmission on '5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7' of Response 103: Match Found [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> BYE sip:6038681300@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK5035b4ad;rport^M From: ;tag=as1bce2215^M To: "6038681300" ;tag=as7d67c2e8^M Call-ID: 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7^M CSeq: 104 BYE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:04] VERBOSE[2812] logger.c: --- (9 headers 0 lines) --- [Jun 3 15:33:04] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7 [Jun 3 15:33:04] DEBUG[2812] chan_sip.c: Received bye, issuing owner hangup [Jun 3 15:33:04] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK5035b4ad;received=64.19.145.4;rport=5060^M From: ;tag=as1bce2215^M To: "6038681300" ;tag=as7d67c2e8^M Call-ID: 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7^M CSeq: 104 BYE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:04] DEBUG[1120] channel.c: Didn't get a frame from channel: SIP/fsa-mg2-091da298 [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Requested indication 20 on channel Zap/20-1 [Jun 3 15:33:04] DEBUG[1120] channel.c: Bridge stops bridging channels Zap/20-1 and SIP/fsa-mg2-091da298 [Jun 3 15:33:04] DEBUG[1120] channel.c: Hanging up channel 'SIP/fsa-mg2-091da298' [Jun 3 15:33:04] DEBUG[1120] chan_sip.c: Hangup call SIP/fsa-mg2-091da298, SIP callid 5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7) [Jun 3 15:33:04] DEBUG[1120] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-091da298 [Jun 3 15:33:04] DEBUG[1120] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:04] DEBUG[1120] rtp.c: Channel 'Zap/20-1' has no RTP, not doing anything [Jun 3 15:33:04] DEBUG[1120] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 3 15:33:04] DEBUG[1120] app_macro.c: Spawn extension (macro-MTTDial,s,1) exited non-zero on 'Zap/20-1' in macro 'MTTDial' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Spawn extension (macro-MTTDial,s,1) exited non-zero on 'Zap/20-1' [Jun 3 15:33:04] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-091da298 [Jun 3 15:33:04] VERBOSE[1120] logger.c: == Spawn extension (macro-MTTDial, s, 1) exited non-zero on 'Zap/20-1' [Jun 3 15:33:04] DEBUG[1120] channel.c: Soft-Hanging up channel 'Zap/20-1' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Launching 'Macro' [Jun 3 15:33:04] VERBOSE[1120] logger.c: -- Executing [h@macro-MTTDial:1] Macro("Zap/20-1", "writesavedsipcallid") in new stack [Jun 3 15:33:04] DEBUG[1120] pbx.c: Expression result is '0' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Expression result is '2' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Launching 'GotoIf' [Jun 3 15:33:04] VERBOSE[1120] logger.c: -- Executing [s@macro-writesavedsipcallid:1] GotoIf("Zap/20-1", "0?DONE:2") in new stack [Jun 3 15:33:04] VERBOSE[1120] logger.c: -- Goto (macro-writesavedsipcallid,s,2) [Jun 3 15:33:04] DEBUG[1120] app_macro.c: Executed application: GotoIf [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Launching 'Set' [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-091da298 - state 4 (Invalid) [Jun 3 15:33:04] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:04] VERBOSE[2812] logger.c: Really destroying SIP dialog '5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7' Method: BYE [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:04] VERBOSE[1120] logger.c: -- Executing [s@macro-writesavedsipcallid:2] Set("Zap/20-1", "CDR(SIPCALLID2)=5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7") in new stack [Jun 3 15:33:04] DEBUG[1120] app_macro.c: Executed application: Set [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Launching 'NoOp' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Launching 'NoOp' [Jun 3 15:33:04] VERBOSE[1120] logger.c: -- Executing [s@macro-writesavedsipcallid:4] NoOp("Zap/20-1", "ANSWER") in new stack [Jun 3 15:33:04] DEBUG[1120] app_macro.c: Executed application: Noop [Jun 3 15:33:04] DEBUG[1120] channel.c: Hanging up channel 'Zap/20-1' [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: zt_hangup(Zap/20-1) [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/20-1 [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Hangup: channel: 20 index = 0, normal = 30, callwait = -1, thirdcall = -1 [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: disabled echo cancellation on channel 20 [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/20-1 [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Updated conferencing on 20, with 0 conference users [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/20-1 [Jun 3 15:33:04] DEBUG[1120] chan_zap.c: disabled echo cancellation on channel 20 [Jun 3 15:33:04] VERBOSE[1120] logger.c: -- Hungup 'Zap/20-1' [Jun 3 15:33:04] DEBUG[1120] devicestate.c: Notification of state change to be queued on device/channel Zap/20-1 [Jun 3 15:33:04] DEBUG[1120] devicestate.c: Notification of state change to be queued on device/channel Zap/20 [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '6038681300' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '6038681300' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '7328423022' [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for Zap/20-1 - state 0 (Unknown) [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is 'Zap/20-1' [Jun 3 15:33:04] DEBUG[2801] devicestate.c: Changing state for Zap/20 - state 0 (Unknown) [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is 'SIP/fsa-mg2-091da298' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '2008-06-03 15:31:16' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '2008-06-03 15:31:32' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '2008-06-03 15:33:04' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '108' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '92' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is 'ANSWERED' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is 'mg3-1212521476.40276' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '' [Jun 3 15:33:04] DEBUG[1120] pbx.c: Function result is '5e0429a14a0ffa8b0617326271f0b0b2@64.19.145.7' [Jun 3 15:33:04] DEBUG[1092] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[663] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[972] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1159] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[626] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7ee295da;received=64.19.145.7;rport=5060^M From: "9085917028" ;tag=as18fd911e^M To: ;tag=as5c226de6^M Call-ID: 56d906c46baf8a580a34d1203e700582@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 19168 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Stopping retransmission on '56d906c46baf8a580a34d1203e700582@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:05] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:19168 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-09033348 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:19168 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:05] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Strict routing enforced for session 56d906c46baf8a580a34d1203e700582@64.19.145.7 [Jun 3 15:33:05] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:05] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733445509@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK3a46ae59;rport^M From: "9085917028" ;tag=as18fd911e^M To: ;tag=as5c226de6^M Contact: ^M Call-ID: 56d906c46baf8a580a34d1203e700582@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:05] DEBUG[1473] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-09033348 [Jun 3 15:33:05] DEBUG[1473] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:05] VERBOSE[1473] logger.c: -- SIP/fsa-mg2-09033348 answered Zap/11-1 [Jun 3 15:33:05] DEBUG[1473] rtp.c: Channel 'Zap/11-1' has no RTP, not doing anything [Jun 3 15:33:05] DEBUG[1473] pbx.c: Launching 'Set' [Jun 3 15:33:05] VERBOSE[1473] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-09033348", "DB(CHANID/fsa-mg2-09033348)=56d906c46baf8a580a34d1203e700582@64.19.145.7") in new stack [Jun 3 15:33:05] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-09033348 [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:9085917028@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4efbf99f;rport^M From: ;tag=as5c226de6^M To: "9085917028" ;tag=as18fd911e^M Contact: ^M Call-ID: 56d906c46baf8a580a34d1203e700582@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.63.181^M s=session^M c=IN IP4 209.191.63.181^M t=0 0^M m=audio 10008 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:05] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.63.181:10008 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-09033348 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.63.181:10008 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 56d906c46baf8a580a34d1203e700582@64.19.145.7 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-09033348: This call is UP.... [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-09033348 - state 4 (Invalid) [Jun 3 15:33:05] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4efbf99f;received=64.19.145.4;rport=5060^M From: ;tag=as5c226de6^M To: "9085917028" ;tag=as18fd911e^M Call-ID: 56d906c46baf8a580a34d1203e700582@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 10648 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4efbf99f;received=64.19.145.4;rport=5060^M From: ;tag=as5c226de6^M To: "9085917028" ;tag=as18fd911e^M Call-ID: 56d906c46baf8a580a34d1203e700582@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2759 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 10648 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:9085917028@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK2c040dd8;rport^M From: ;tag=as5c226de6^M To: "9085917028" ;tag=as18fd911e^M Contact: ^M Call-ID: 56d906c46baf8a580a34d1203e700582@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Stopping retransmission on '56d906c46baf8a580a34d1203e700582@64.19.145.7' of Response 102: Match Found [Jun 3 15:33:05] DEBUG[1473] app_macro.c: Executed application: Set [Jun 3 15:33:05] DEBUG[1473] app_dial.c: Macro exited with status 0 [Jun 3 15:33:05] DEBUG[1473] chan_zap.c: Requested indication -1 on channel Zap/11-1 [Jun 3 15:33:05] DEBUG[1473] devicestate.c: Notification of state change to be queued on device/channel Zap/11-1 [Jun 3 15:33:05] DEBUG[1473] devicestate.c: Notification of state change to be queued on device/channel Zap/11 [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for Zap/11-1 - state 0 (Unknown) [Jun 3 15:33:05] DEBUG[2801] channel.c: Avoiding initial deadlock for channel '0x909ad80' [Jun 3 15:33:05] DEBUG[1473] chan_zap.c: Requested indication 20 on channel Zap/11-1 [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for Zap/11 - state 2 (In use) [Jun 3 15:33:05] DEBUG[1144] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1473] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:05] DEBUG[1473] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:05] DEBUG[1473] rtp.c: RTP NAT: Got audio from other end. Now sending to address 64.19.145.4:19168 [Jun 3 15:33:05] DEBUG[1473] rtp.c: RTP NAT: Got audio from other end. Now sending to address 209.191.63.181:10008 [Jun 3 15:33:05] DEBUG[18048] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:05] DEBUG[1105] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1190] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[18493] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:05] DEBUG[1020] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1048] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1151] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:05] DEBUG[1181] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1123] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1460] chan_zap.c: DTMF digit: 0 on Zap/92-1 [Jun 3 15:33:05] DEBUG[1460] channel.c: Set channel SIP/fsa-mg2-0914f438 to write format slin [Jun 3 15:33:05] DEBUG[1460] channel.c: Scheduling timer at 160 sample intervals [Jun 3 15:33:05] DEBUG[1462] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1460] channel.c: Generator got voice, switching to phase locked mode [Jun 3 15:33:05] DEBUG[1460] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:05] DEBUG[961] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1069] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1042] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[493] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[493] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1141] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1460] channel.c: Set channel SIP/fsa-mg2-0914f438 to write format ulaw [Jun 3 15:33:05] DEBUG[1460] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:05] DEBUG[1460] channel.c: Thread 20093856 Blocking 'SIP/fsa-mg2-0914f438', already blocked by thread 20093856 in procedure ast_write [Jun 3 15:33:05] VERBOSE[2822] logger.c: -- Accepting call from '6104159311' to '7322518000' on channel 0/20, span 1 [Jun 3 15:33:05] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 20 [Jun 3 15:33:05] DEBUG[1189] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:05] DEBUG[1478] pbx.c: Launching 'Macro' [Jun 3 15:33:05] VERBOSE[1478] logger.c: -- Executing [7322518000@default:1] Macro("Zap/20-1", "MTTDial|SIP/7322518000@fsa-mg2") in new stack [Jun 3 15:33:05] DEBUG[1478] pbx.c: Launching 'Dial' [Jun 3 15:33:05] VERBOSE[1478] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/20-1", "SIP/7322518000@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:05] DEBUG[1478] rtp.c: Channel 'Zap/20-1' has no RTP, not doing anything [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable ARG1. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable ANI2. [Jun 3 15:33:05] DEBUG[1478] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Outgoing Call for 7322518000 [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[1478] logger.c: Audio is at 64.19.145.7 port 13504 [Jun 3 15:33:05] VERBOSE[1478] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:05] DEBUG[1478] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[1478] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7322518000@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK5de2fb41;rport^M From: "6104159311" ;tag=as4aab9bcc^M To: ^M Contact: ^M Call-ID: 7d835cba5f74b8617fd619896ca46361@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:05 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13504 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:05] VERBOSE[1478] logger.c: -- Called 7322518000@fsa-mg2 [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK5de2fb41;received=64.19.145.7;rport=5060^M From: "6104159311" ;tag=as4aab9bcc^M To: ;tag=as516ae2e3^M Call-ID: 7d835cba5f74b8617fd619896ca46361@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="19bd2a61"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Stopping retransmission on '7d835cba5f74b8617fd619896ca46361@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:05] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7322518000@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK5de2fb41;rport^M From: "6104159311" ;tag=as4aab9bcc^M To: ;tag=as516ae2e3^M Contact: ^M Call-ID: 7d835cba5f74b8617fd619896ca46361@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 13504 [Jun 3 15:33:05] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:05] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7322518000@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK0090c306;rport^M From: "6104159311" ;tag=as4aab9bcc^M To: ^M Contact: ^M Call-ID: 7d835cba5f74b8617fd619896ca46361@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:7322518000@64.19.145.4", nonce="19bd2a61", response="bf111f7b9796c8b0be41fafd46c4a695"^M Date: Tue, 03 Jun 2008 19:33:05 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13504 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK0090c306;received=64.19.145.7;rport=5060^M From: "6104159311" ;tag=as4aab9bcc^M To: ^M Call-ID: 7d835cba5f74b8617fd619896ca46361@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7d835cba5f74b8617fd619896ca46361@64.19.145.7' Request 103: Found [Jun 3 15:33:05] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK0090c306;received=64.19.145.7;rport=5060^M From: "6104159311" ;tag=as4aab9bcc^M To: ;tag=as3d3dbd4e^M Call-ID: 7d835cba5f74b8617fd619896ca46361@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:05] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:05] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7d835cba5f74b8617fd619896ca46361@64.19.145.7' Request 103: Found [Jun 3 15:33:05] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-091da298 [Jun 3 15:33:05] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:05] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-091da298 [Jun 3 15:33:05] VERBOSE[1478] logger.c: -- SIP/fsa-mg2-091da298 is ringing [Jun 3 15:33:05] DEBUG[1478] rtp.c: Channel 'Zap/20-1' has no RTP, not doing anything [Jun 3 15:33:05] DEBUG[1478] chan_zap.c: Requested indication 3 on channel Zap/20-1 [Jun 3 15:33:05] DEBUG[1478] devicestate.c: Notification of state change to be queued on device/channel Zap/20-1 [Jun 3 15:33:05] DEBUG[1478] devicestate.c: Notification of state change to be queued on device/channel Zap/20 [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-091da298 - state 4 (Invalid) [Jun 3 15:33:05] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for Zap/20-1 - state 0 (Unknown) [Jun 3 15:33:05] DEBUG[2801] devicestate.c: Changing state for Zap/20 - state 6 (Ringing) [Jun 3 15:33:06] DEBUG[1184] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1139] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1154] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1467] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 64.19.145.4:13671 [Jun 3 15:33:06] DEBUG[1467] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:06] DEBUG[32411] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[607] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1179] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1096] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1177] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK0231d0fb;received=64.19.145.7;rport=5060^M From: "6096558676" ;tag=as25e6d06b^M To: ;tag=as67a49097^M Call-ID: 094bd8d369519a1374861b6130322d94@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 10846 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '094bd8d369519a1374861b6130322d94@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:10846 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-09173840 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:10846 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:06] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Strict routing enforced for session 094bd8d369519a1374861b6130322d94@64.19.145.7 [Jun 3 15:33:06] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:06] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7323632901@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK77b62e29;rport^M From: "6096558676" ;tag=as25e6d06b^M To: ;tag=as67a49097^M Contact: ^M Call-ID: 094bd8d369519a1374861b6130322d94@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:06] DEBUG[1469] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-09173840 [Jun 3 15:33:06] DEBUG[1469] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:06] VERBOSE[1469] logger.c: -- SIP/fsa-mg2-09173840 answered Zap/108-1 [Jun 3 15:33:06] DEBUG[1469] rtp.c: Channel 'Zap/108-1' has no RTP, not doing anything [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-09173840 [Jun 3 15:33:06] DEBUG[1469] pbx.c: Launching 'Set' [Jun 3 15:33:06] VERBOSE[1469] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-09173840", "DB(CHANID/fsa-mg2-09173840)=094bd8d369519a1374861b6130322d94@64.19.145.7") in new stack [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:6096558676@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK0b123bb0;rport^M From: ;tag=as67a49097^M To: "6096558676" ;tag=as25e6d06b^M Contact: ^M Call-ID: 094bd8d369519a1374861b6130322d94@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.63.164^M s=session^M c=IN IP4 209.191.63.164^M t=0 0^M m=audio 10012 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:06] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.63.164:10012 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-09173840 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-09173840 - state 4 (Invalid) [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.63.164:10012 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 094bd8d369519a1374861b6130322d94@64.19.145.7 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-09173840: This call is UP.... [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK0b123bb0;received=64.19.145.4;rport=5060^M From: ;tag=as67a49097^M To: "6096558676" ;tag=as25e6d06b^M Call-ID: 094bd8d369519a1374861b6130322d94@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 14646 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK0b123bb0;received=64.19.145.4;rport=5060^M From: ;tag=as67a49097^M To: "6096558676" ;tag=as25e6d06b^M Call-ID: 094bd8d369519a1374861b6130322d94@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2759 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 14646 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:6096558676@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK29d355ee;rport^M From: ;tag=as67a49097^M To: "6096558676" ;tag=as25e6d06b^M Contact: ^M Call-ID: 094bd8d369519a1374861b6130322d94@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '094bd8d369519a1374861b6130322d94@64.19.145.7' of Response 102: Match Found [Jun 3 15:33:06] DEBUG[1152] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1469] app_macro.c: Executed application: Set [Jun 3 15:33:06] DEBUG[1469] app_dial.c: Macro exited with status 0 [Jun 3 15:33:06] DEBUG[1469] chan_zap.c: Requested indication -1 on channel Zap/108-1 [Jun 3 15:33:06] DEBUG[1469] devicestate.c: Notification of state change to be queued on device/channel Zap/108-1 [Jun 3 15:33:06] DEBUG[1469] devicestate.c: Notification of state change to be queued on device/channel Zap/108 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/108-1 - state 0 (Unknown) [Jun 3 15:33:06] DEBUG[2801] channel.c: Avoiding initial deadlock for channel '0x90e3a48' [Jun 3 15:33:06] DEBUG[1469] chan_zap.c: Requested indication 20 on channel Zap/108-1 [Jun 3 15:33:06] DEBUG[1469] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:06] DEBUG[1469] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/108 - state 2 (In use) [Jun 3 15:33:06] DEBUG[1469] rtp.c: RTP NAT: Got audio from other end. Now sending to address 64.19.145.4:10846 [Jun 3 15:33:06] DEBUG[18011] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:06] DEBUG[1469] rtp.c: RTP NAT: Got audio from other end. Now sending to address 209.191.63.164:10012 [Jun 3 15:33:06] VERBOSE[2822] logger.c: -- Accepting call from '7575628500' to '9733797400' on channel 3/18, span 1 [Jun 3 15:33:06] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 114 [Jun 3 15:33:06] DEBUG[1479] pbx.c: Launching 'Macro' [Jun 3 15:33:06] VERBOSE[1479] logger.c: -- Executing [9733797400@default:1] Macro("Zap/114-1", "MTTDial|SIP/9733797400@fsa-mg2") in new stack [Jun 3 15:33:06] DEBUG[1479] pbx.c: Launching 'Dial' [Jun 3 15:33:06] VERBOSE[1479] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/114-1", "SIP/9733797400@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:06] DEBUG[1479] rtp.c: Channel 'Zap/114-1' has no RTP, not doing anything [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable ARG1. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable ANI2. [Jun 3 15:33:06] DEBUG[1479] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Outgoing Call for 9733797400 [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[1479] logger.c: Audio is at 64.19.145.7 port 18702 [Jun 3 15:33:06] VERBOSE[1479] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[1479] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[1479] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9733797400@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK2ebd1898;rport^M From: "7575628500" ;tag=as1567cdb8^M To: ^M Contact: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:06 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 18702 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:06] VERBOSE[1479] logger.c: -- Called 9733797400@fsa-mg2 [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK2ebd1898;received=64.19.145.7;rport=5060^M From: "7575628500" ;tag=as1567cdb8^M To: ;tag=as25fd5258^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7406f1a2"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '55197a40747494d627207bef03a79e69@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:06] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733797400@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK2ebd1898;rport^M From: "7575628500" ;tag=as1567cdb8^M To: ;tag=as25fd5258^M Contact: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 18702 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9733797400@64.19.145.4 SIP/2.0^M From: "7575628500" ;tag=as1567cdb8^M To: ^M Contact: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:9733797400@64.19.145.4", nonce="7406f1a2", response="93bd0373c2b5892564279f24debec0e3"^M Date: Tue, 03 Jun 2008 19:33:06 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 18702 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK57379610;received=64.19.145.7;rport=5060^M From: "7575628500" ;tag=as1567cdb8^M To: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '55197a40747494d627207bef03a79e69@64.19.145.7' Request 103: Found [Jun 3 15:33:06] VERBOSE[2823] logger.c: -- Accepting call from '6095852444' to '7325313003' on channel 0/18, span 4 [Jun 3 15:33:06] DEBUG[2823] chan_zap.c: Enabled echo cancellation on channel 90 [Jun 3 15:33:06] DEBUG[1480] pbx.c: Launching 'Macro' [Jun 3 15:33:06] VERBOSE[1480] logger.c: -- Executing [7325313003@default:1] Macro("Zap/90-1", "MTTDial|SIP/7325313003@fsa-mg2") in new stack [Jun 3 15:33:06] DEBUG[1480] pbx.c: Launching 'Dial' [Jun 3 15:33:06] VERBOSE[1480] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/90-1", "SIP/7325313003@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:06] DEBUG[1480] rtp.c: Channel 'Zap/90-1' has no RTP, not doing anything [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable ARG1. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable ANI2. [Jun 3 15:33:06] DEBUG[1480] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Outgoing Call for 7325313003 [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[1480] logger.c: Audio is at 64.19.145.7 port 17254 [Jun 3 15:33:06] VERBOSE[1480] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[1480] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[1480] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7325313003@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK3e4ddfb1;rport^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ^M Contact: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:06 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 17254 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:06] VERBOSE[1480] logger.c: -- Called 7325313003@fsa-mg2 [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK3e4ddfb1;received=64.19.145.7;rport=5060^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ;tag=as19254c6c^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="70d0a70d"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '09c813e7261c4925642b0c1f1cba296b@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:06] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7325313003@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK3e4ddfb1;rport^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ;tag=as19254c6c^M Contact: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 17254 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7325313003@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK62b41c89;rport^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ^M Contact: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:7325313003@64.19.145.4", nonce="70d0a70d", response="3edc44ed9b726c72a156a0fa2efc8857"^M Date: Tue, 03 Jun 2008 19:33:06 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 17254 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK62b41c89;received=64.19.145.7;rport=5060^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '09c813e7261c4925642b0c1f1cba296b@64.19.145.7' Request 103: Found [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK57379610;received=64.19.145.7;rport=5060^M From: "7575628500" ;tag=as1567cdb8^M To: ;tag=as5f1bc55b^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '55197a40747494d627207bef03a79e69@64.19.145.7' Request 103: Found [Jun 3 15:33:06] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08e821a8 [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08e821a8 [Jun 3 15:33:06] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:06] VERBOSE[1479] logger.c: -- SIP/fsa-mg2-08e821a8 is ringing [Jun 3 15:33:06] DEBUG[1479] rtp.c: Channel 'Zap/114-1' has no RTP, not doing anything [Jun 3 15:33:06] DEBUG[1479] chan_zap.c: Requested indication 3 on channel Zap/114-1 [Jun 3 15:33:06] DEBUG[1479] devicestate.c: Notification of state change to be queued on device/channel Zap/114-1 [Jun 3 15:33:06] DEBUG[1479] devicestate.c: Notification of state change to be queued on device/channel Zap/114 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08e821a8 - state 4 (Invalid) [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/114-1 - state 0 (Unknown) [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/114 - state 6 (Ringing) [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK01bac26d;received=64.19.145.7;rport=5060^M From: "2486434894" ;tag=as14a5837b^M To: ;tag=as3bad6ca2^M Call-ID: 18fd2f5b077050aa7841fc546487a482@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 19850 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '18fd2f5b077050aa7841fc546487a482@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:19850 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08f8cd90 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:19850 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:06] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Strict routing enforced for session 18fd2f5b077050aa7841fc546487a482@64.19.145.7 [Jun 3 15:33:06] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:06] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733765605@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK5074f451;rport^M From: "2486434894" ;tag=as14a5837b^M To: ;tag=as3bad6ca2^M Contact: ^M Call-ID: 18fd2f5b077050aa7841fc546487a482@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:06] DEBUG[1470] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08f8cd90 [Jun 3 15:33:06] DEBUG[1470] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08f8cd90 [Jun 3 15:33:06] VERBOSE[1470] logger.c: -- SIP/fsa-mg2-08f8cd90 answered Zap/109-1 [Jun 3 15:33:06] DEBUG[1470] rtp.c: Channel 'Zap/109-1' has no RTP, not doing anything [Jun 3 15:33:06] DEBUG[1470] pbx.c: Launching 'Set' [Jun 3 15:33:06] VERBOSE[1470] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-08f8cd90", "DB(CHANID/fsa-mg2-08f8cd90)=18fd2f5b077050aa7841fc546487a482@64.19.145.7") in new stack [Jun 3 15:33:06] DEBUG[1470] app_macro.c: Executed application: Set [Jun 3 15:33:06] DEBUG[1470] app_dial.c: Macro exited with status 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:2486434894@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK02d04448;rport^M From: ;tag=as3bad6ca2^M To: "2486434894" ;tag=as14a5837b^M Contact: ^M Call-ID: 18fd2f5b077050aa7841fc546487a482@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.18.183^M s=session^M c=IN IP4 209.191.18.183^M t=0 0^M m=audio 10002 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:06] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08f8cd90 - state 4 (Invalid) [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.18.183:10002 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08f8cd90 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.18.183:10002 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 18fd2f5b077050aa7841fc546487a482@64.19.145.7 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-08f8cd90: This call is UP.... [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK02d04448;received=64.19.145.4;rport=5060^M From: ;tag=as3bad6ca2^M To: "2486434894" ;tag=as14a5837b^M Call-ID: 18fd2f5b077050aa7841fc546487a482@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 19006 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK02d04448;received=64.19.145.4;rport=5060^M From: ;tag=as3bad6ca2^M To: "2486434894" ;tag=as14a5837b^M Call-ID: 18fd2f5b077050aa7841fc546487a482@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2759 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 19006 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:2486434894@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK50637d56;rport^M From: ;tag=as3bad6ca2^M To: "2486434894" ;tag=as14a5837b^M Contact: ^M Call-ID: 18fd2f5b077050aa7841fc546487a482@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '18fd2f5b077050aa7841fc546487a482@64.19.145.7' of Response 102: Match Found [Jun 3 15:33:06] DEBUG[1470] chan_zap.c: Requested indication -1 on channel Zap/109-1 [Jun 3 15:33:06] DEBUG[1470] devicestate.c: Notification of state change to be queued on device/channel Zap/109-1 [Jun 3 15:33:06] DEBUG[1470] devicestate.c: Notification of state change to be queued on device/channel Zap/109 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/109-1 - state 0 (Unknown) [Jun 3 15:33:06] DEBUG[2801] channel.c: Avoiding initial deadlock for channel '0x924c2d8' [Jun 3 15:33:06] DEBUG[1470] chan_zap.c: Requested indication 20 on channel Zap/109-1 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/109 - state 2 (In use) [Jun 3 15:33:06] DEBUG[1470] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:06] DEBUG[1470] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:06] DEBUG[1470] rtp.c: RTP NAT: Got audio from other end. Now sending to address 64.19.145.4:19850 [Jun 3 15:33:06] DEBUG[1470] rtp.c: RTP NAT: Got audio from other end. Now sending to address 209.191.18.183:10002 [Jun 3 15:33:06] DEBUG[1136] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1114] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[32598] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[450] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK62b41c89;received=64.19.145.7;rport=5060^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ;tag=as2ec63740^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 12194 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '09c813e7261c4925642b0c1f1cba296b@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:12194 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08f2e058 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:12194 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:06] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Strict routing enforced for session 09c813e7261c4925642b0c1f1cba296b@64.19.145.7 [Jun 3 15:33:06] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:06] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7325313003@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK60e4c229;rport^M From: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M To: ;tag=as2ec63740^M Contact: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:06] DEBUG[1480] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08f2e058 [Jun 3 15:33:06] DEBUG[1480] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:06] VERBOSE[1480] logger.c: -- SIP/fsa-mg2-08f2e058 answered Zap/90-1 [Jun 3 15:33:06] DEBUG[1480] rtp.c: Channel 'Zap/90-1' has no RTP, not doing anything [Jun 3 15:33:06] DEBUG[1480] pbx.c: Launching 'Set' [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08f2e058 [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:6095852444@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK52a29eff;rport^M From: ;tag=as2ec63740^M To: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M Contact: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 186^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.33.80^M s=session^M c=IN IP4 209.191.33.80^M t=0 0^M m=audio 10000 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:06] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.33.80:10000 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08f2e058 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.33.80:10000 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 09c813e7261c4925642b0c1f1cba296b@64.19.145.7 [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-08f2e058: This call is UP.... [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK52a29eff;received=64.19.145.4;rport=5060^M From: ;tag=as2ec63740^M To: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:06] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 17254 [Jun 3 15:33:06] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08f2e058 - state 4 (Invalid) [Jun 3 15:33:06] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK52a29eff;received=64.19.145.4;rport=5060^M From: ;tag=as2ec63740^M To: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2759 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 17254 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:06] VERBOSE[1480] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-08f2e058", "DB(CHANID/fsa-mg2-08f2e058)=09c813e7261c4925642b0c1f1cba296b@64.19.145.7") in new stack [Jun 3 15:33:06] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:6095852444@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK7749c21c;rport^M From: ;tag=as2ec63740^M To: "ANGEBRANNDT PHI" ;tag=as36c60ffb^M Contact: ^M Call-ID: 09c813e7261c4925642b0c1f1cba296b@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:06] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:06] DEBUG[2812] chan_sip.c: Stopping retransmission on '09c813e7261c4925642b0c1f1cba296b@64.19.145.7' of Response 102: Match Found [Jun 3 15:33:06] DEBUG[1480] app_macro.c: Executed application: Set [Jun 3 15:33:06] DEBUG[1480] app_dial.c: Macro exited with status 0 [Jun 3 15:33:06] DEBUG[1480] devicestate.c: Notification of state change to be queued on device/channel Zap/90-1 [Jun 3 15:33:06] DEBUG[1480] devicestate.c: Notification of state change to be queued on device/channel Zap/90 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/90-1 - state 0 (Unknown) [Jun 3 15:33:06] DEBUG[2801] channel.c: Avoiding initial deadlock for channel '0xb7af5180' [Jun 3 15:33:06] DEBUG[1480] chan_zap.c: Requested indication 20 on channel Zap/90-1 [Jun 3 15:33:06] DEBUG[2801] devicestate.c: Changing state for Zap/90 - state 2 (In use) [Jun 3 15:33:06] DEBUG[1480] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:06] DEBUG[1480] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:06] DEBUG[1084] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:06] DEBUG[1155] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] DEBUG[18821] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:07] VERBOSE[2822] logger.c: -- Accepting call from '8477509300' to '9733767130' on channel 3/19, span 1 [Jun 3 15:33:07] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 115 [Jun 3 15:33:07] DEBUG[1481] pbx.c: Launching 'Macro' [Jun 3 15:33:07] VERBOSE[1481] logger.c: -- Executing [9733767130@default:1] Macro("Zap/115-1", "MTTDial|SIP/9733767130@fsa-mg2") in new stack [Jun 3 15:33:07] DEBUG[1481] pbx.c: Launching 'Dial' [Jun 3 15:33:07] VERBOSE[1481] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/115-1", "SIP/9733767130@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:07] DEBUG[1481] rtp.c: Channel 'Zap/115-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable ARG1. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable ANI2. [Jun 3 15:33:07] DEBUG[1481] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Outgoing Call for 9733767130 [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[1481] logger.c: Audio is at 64.19.145.7 port 13582 [Jun 3 15:33:07] VERBOSE[1481] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[1481] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[1481] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9733767130@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK27565941;rport^M From: "8477509300" ;tag=as7b22c5ee^M To: ^M Contact: ^M Call-ID: 2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:07 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13582 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:07] VERBOSE[1481] logger.c: -- Called 9733767130@fsa-mg2 [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK27565941;received=64.19.145.7;rport=5060^M From: "8477509300" ;tag=as7b22c5ee^M To: ;tag=as504d96ea^M Call-ID: 2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1e318590"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Stopping retransmission on '2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:07] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733767130@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK27565941;rport^M From: "8477509300" ;tag=as7b22c5ee^M To: ;tag=as504d96ea^M Contact: ^M Call-ID: 2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 13582 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9733767130@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6bdaa792;rport^M From: "8477509300" ;tag=as7b22c5ee^M To: ^M Contact: ^M Call-ID: 2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:9733767130@64.19.145.4", nonce="1e318590", response="0aa88d715ca486656b93ac3c38c70d99"^M Date: Tue, 03 Jun 2008 19:33:07 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13582 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6bdaa792;received=64.19.145.7;rport=5060^M From: "8477509300" ;tag=as7b22c5ee^M To: ^M Call-ID: 2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7' Request 103: Found [Jun 3 15:33:07] VERBOSE[2822] logger.c: -- Accepting call from '7327470808' to '7328639600' on channel 3/20, span 1 [Jun 3 15:33:07] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 116 [Jun 3 15:33:07] DEBUG[1482] pbx.c: Launching 'Macro' [Jun 3 15:33:07] VERBOSE[1482] logger.c: -- Executing [7328639600@default:1] Macro("Zap/116-1", "MTTDial|SIP/7328639600@fsa-mg2") in new stack [Jun 3 15:33:07] DEBUG[1482] pbx.c: Launching 'Dial' [Jun 3 15:33:07] VERBOSE[1482] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/116-1", "SIP/7328639600@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:07] DEBUG[1482] rtp.c: Channel 'Zap/116-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable ARG1. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable ANI2. [Jun 3 15:33:07] DEBUG[1482] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Outgoing Call for 7328639600 [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[1482] logger.c: Audio is at 64.19.145.7 port 12252 [Jun 3 15:33:07] VERBOSE[1482] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[1482] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[1482] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7328639600@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6c8def30;rport^M From: "7327470808" ;tag=as70f362fb^M To: ^M Contact: ^M Call-ID: 7f07ada20693320b39edff9c70b40f97@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:07 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 12252 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:07] VERBOSE[1482] logger.c: -- Called 7328639600@fsa-mg2 [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6c8def30;received=64.19.145.7;rport=5060^M From: "7327470808" ;tag=as70f362fb^M To: ;tag=as4583a902^M Call-ID: 7f07ada20693320b39edff9c70b40f97@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="676798c3"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Stopping retransmission on '7f07ada20693320b39edff9c70b40f97@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:07] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7328639600@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6c8def30;rport^M From: "7327470808" ;tag=as70f362fb^M To: ;tag=as4583a902^M Contact: ^M Call-ID: 7f07ada20693320b39edff9c70b40f97@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 12252 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7328639600@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK68b9f231;rport^M From: "7327470808" ;tag=as70f362fb^M To: ^M Contact: ^M Call-ID: 7f07ada20693320b39edff9c70b40f97@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:7328639600@64.19.145.4", nonce="676798c3", response="5ca05dfb6031b7bb52217ff72d9f5f38"^M Date: Tue, 03 Jun 2008 19:33:07 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 12252 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK68b9f231;received=64.19.145.7;rport=5060^M From: "7327470808" ;tag=as70f362fb^M To: ^M Call-ID: 7f07ada20693320b39edff9c70b40f97@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7f07ada20693320b39edff9c70b40f97@64.19.145.7' Request 103: Found [Jun 3 15:33:07] DEBUG[1168] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK68b9f231;received=64.19.145.7;rport=5060^M From: "7327470808" ;tag=as70f362fb^M To: ;tag=as74a1013a^M Call-ID: 7f07ada20693320b39edff9c70b40f97@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7f07ada20693320b39edff9c70b40f97@64.19.145.7' Request 103: Found [Jun 3 15:33:07] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08fa15c0 [Jun 3 15:33:07] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08fa15c0 [Jun 3 15:33:07] VERBOSE[1482] logger.c: -- SIP/fsa-mg2-08fa15c0 is ringing [Jun 3 15:33:07] DEBUG[1482] rtp.c: Channel 'Zap/116-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1482] chan_zap.c: Requested indication 3 on channel Zap/116-1 [Jun 3 15:33:07] DEBUG[1482] devicestate.c: Notification of state change to be queued on device/channel Zap/116-1 [Jun 3 15:33:07] DEBUG[1482] devicestate.c: Notification of state change to be queued on device/channel Zap/116 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08fa15c0 - state 4 (Invalid) [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/116-1 - state 0 (Unknown) [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/116 - state 6 (Ringing) [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6bdaa792;received=64.19.145.7;rport=5060^M From: "8477509300" ;tag=as7b22c5ee^M To: ;tag=as2b8a4078^M Call-ID: 2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2599a8f44c57d45b48b74ad35e1f188b@64.19.145.7' Request 103: Found [Jun 3 15:33:07] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08eea558 [Jun 3 15:33:07] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08eea558 [Jun 3 15:33:07] VERBOSE[1481] logger.c: -- SIP/fsa-mg2-08eea558 is ringing [Jun 3 15:33:07] DEBUG[1481] rtp.c: Channel 'Zap/115-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1481] chan_zap.c: Requested indication 3 on channel Zap/115-1 [Jun 3 15:33:07] DEBUG[1481] devicestate.c: Notification of state change to be queued on device/channel Zap/115-1 [Jun 3 15:33:07] DEBUG[1481] devicestate.c: Notification of state change to be queued on device/channel Zap/115 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08eea558 - state 4 (Invalid) [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/115-1 - state 0 (Unknown) [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/115 - state 6 (Ringing) [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK57379610;received=64.19.145.7;rport=5060^M From: "7575628500" ;tag=as1567cdb8^M To: ;tag=as5f1bc55b^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 15716 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Stopping retransmission on '55197a40747494d627207bef03a79e69@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:07] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:15716 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08e821a8 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:15716 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:07] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Strict routing enforced for session 55197a40747494d627207bef03a79e69@64.19.145.7 [Jun 3 15:33:07] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:07] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733797400@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK2644c3a7;rport^M From: "7575628500" ;tag=as1567cdb8^M To: ;tag=as5f1bc55b^M Contact: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:07] DEBUG[1479] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08e821a8 [Jun 3 15:33:07] DEBUG[1479] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08e821a8 [Jun 3 15:33:07] VERBOSE[1479] logger.c: -- SIP/fsa-mg2-08e821a8 answered Zap/114-1 [Jun 3 15:33:07] DEBUG[1479] rtp.c: Channel 'Zap/114-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1479] pbx.c: Launching 'Set' [Jun 3 15:33:07] VERBOSE[1479] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-08e821a8", "DB(CHANID/fsa-mg2-08e821a8)=55197a40747494d627207bef03a79e69@64.19.145.7") in new stack [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:7575628500@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK735c067e;rport^M From: ;tag=as5f1bc55b^M To: "7575628500" ;tag=as1567cdb8^M Contact: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.49.185^M s=session^M c=IN IP4 209.191.49.185^M t=0 0^M m=audio 10000 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:07] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.49.185:10000 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08e821a8 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.49.185:10000 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 55197a40747494d627207bef03a79e69@64.19.145.7 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-08e821a8: This call is UP.... [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08e821a8 - state 4 (Invalid) [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK735c067e;received=64.19.145.4;rport=5060^M From: ;tag=as5f1bc55b^M To: "7575628500" ;tag=as1567cdb8^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 18702 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK735c067e;received=64.19.145.4;rport=5060^M From: ;tag=as5f1bc55b^M To: "7575628500" ;tag=as1567cdb8^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2759 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 18702 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:07] DEBUG[676] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:7575628500@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK67bcbd3e;rport^M From: ;tag=as5f1bc55b^M To: "7575628500" ;tag=as1567cdb8^M Contact: ^M Call-ID: 55197a40747494d627207bef03a79e69@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Stopping retransmission on '55197a40747494d627207bef03a79e69@64.19.145.7' of Response 102: Match Found [Jun 3 15:33:07] DEBUG[1479] app_macro.c: Executed application: Set [Jun 3 15:33:07] DEBUG[1479] app_dial.c: Macro exited with status 0 [Jun 3 15:33:07] DEBUG[1479] chan_zap.c: Requested indication -1 on channel Zap/114-1 [Jun 3 15:33:07] DEBUG[1479] devicestate.c: Notification of state change to be queued on device/channel Zap/114-1 [Jun 3 15:33:07] DEBUG[1479] devicestate.c: Notification of state change to be queued on device/channel Zap/114 [Jun 3 15:33:07] DEBUG[1479] chan_zap.c: Requested indication 20 on channel Zap/114-1 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/114-1 - state 0 (Unknown) [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/114 - state 2 (In use) [Jun 3 15:33:07] DEBUG[520] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] DEBUG[1479] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:07] DEBUG[1479] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:07] DEBUG[1479] rtp.c: RTP NAT: Got audio from other end. Now sending to address 64.19.145.4:15716 [Jun 3 15:33:07] DEBUG[1479] rtp.c: RTP NAT: Got audio from other end. Now sending to address 209.191.49.185:10000 [Jun 3 15:33:07] DEBUG[1463] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] DEBUG[1165] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] DEBUG[1464] chan_zap.c: DTMF digit: 1 on Zap/66-1 [Jun 3 15:33:07] DEBUG[1464] channel.c: Set channel SIP/fsa-mg2-090c2ed0 to write format slin [Jun 3 15:33:07] DEBUG[1464] channel.c: Scheduling timer at 160 sample intervals [Jun 3 15:33:07] DEBUG[1464] channel.c: Generator got voice, switching to phase locked mode [Jun 3 15:33:07] DEBUG[1464] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:07] DEBUG[1170] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] DEBUG[1464] channel.c: Set channel SIP/fsa-mg2-090c2ed0 to write format ulaw [Jun 3 15:33:07] DEBUG[1464] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:07] DEBUG[1464] channel.c: Thread 58997664 Blocking 'SIP/fsa-mg2-090c2ed0', already blocked by thread 58997664 in procedure ast_write [Jun 3 15:33:07] DEBUG[1101] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] VERBOSE[2822] logger.c: -- Accepting call from '8484481955' to '7329422283' on channel 3/21, span 1 [Jun 3 15:33:07] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 117 [Jun 3 15:33:07] DEBUG[1483] pbx.c: Launching 'Macro' [Jun 3 15:33:07] VERBOSE[1483] logger.c: -- Executing [7329422283@default:1] Macro("Zap/117-1", "MTTDial|SIP/7329422283@fsa-mg2") in new stack [Jun 3 15:33:07] DEBUG[1483] pbx.c: Launching 'Dial' [Jun 3 15:33:07] VERBOSE[1483] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/117-1", "SIP/7329422283@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:07] DEBUG[1483] rtp.c: Channel 'Zap/117-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable ARG1. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable ANI2. [Jun 3 15:33:07] DEBUG[1483] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Outgoing Call for 7329422283 [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[1483] logger.c: Audio is at 64.19.145.7 port 15862 [Jun 3 15:33:07] VERBOSE[1483] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[1483] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7329422283@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7400a4e4;rport^M From: "8484481955" ;tag=as0087f4c2^M To: ^M Contact: ^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:07 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 15862 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:07] VERBOSE[1483] logger.c: -- Called 7329422283@fsa-mg2 [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7400a4e4;received=64.19.145.7;rport=5060^M From: "8484481955" ;tag=as0087f4c2^M To: ;tag=as2d396985^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="21df049f"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Stopping retransmission on '6c2319050d7565b4534d8aff52df8250@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:07] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7329422283@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7400a4e4;rport^M From: "8484481955" ;tag=as0087f4c2^M To: ;tag=as2d396985^M Contact: ^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 15862 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:07] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7329422283@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK76e9bc8e;rport^M From: "8484481955" ;tag=as0087f4c2^M To: ^M Contact: ^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:7329422283@64.19.145.4", nonce="21df049f", response="7189039ae280734ba09e9a1aaf540678"^M Date: Tue, 03 Jun 2008 19:33:07 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 15862 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:07] DEBUG[1102] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK76e9bc8e;received=64.19.145.7;rport=5060^M From: "8484481955" ;tag=as0087f4c2^M To: ^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6c2319050d7565b4534d8aff52df8250@64.19.145.7' Request 103: Found [Jun 3 15:33:07] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 486 Busy Here^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK76e9bc8e;received=64.19.145.7;rport=5060^M From: "8484481955" ;tag=as0087f4c2^M To: ;tag=as63ebd0be^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Length: 0^M X-Asterisk-HangupCause: User busy^M X-Asterisk-HangupCauseCode: 17^M ^M <-------------> [Jun 3 15:33:07] VERBOSE[2812] logger.c: --- (12 headers 0 lines) --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Stopping retransmission on '6c2319050d7565b4534d8aff52df8250@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:07] VERBOSE[2812] logger.c: -- Got SIP response 486 "Busy Here" back from 64.19.145.4 [Jun 3 15:33:07] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7329422283@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK76e9bc8e;rport^M From: "8484481955" ;tag=as0087f4c2^M To: ;tag=as63ebd0be^M Contact: ^M Call-ID: 6c2319050d7565b4534d8aff52df8250@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:07] DEBUG[2812] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6c2319050d7565b4534d8aff52df8250@64.19.145.7 [Jun 3 15:33:07] VERBOSE[1483] logger.c: -- SIP/fsa-mg2-09270d58 is busy [Jun 3 15:33:07] DEBUG[1483] channel.c: Hanging up channel 'SIP/fsa-mg2-09270d58' [Jun 3 15:33:07] DEBUG[1483] chan_sip.c: Hangup call SIP/fsa-mg2-09270d58, SIP callid 6c2319050d7565b4534d8aff52df8250@64.19.145.7) [Jun 3 15:33:07] DEBUG[1483] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-09270d58 [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-09270d58 [Jun 3 15:33:07] DEBUG[1483] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:07] VERBOSE[1483] logger.c: == Everyone is busy/congested at this time (1:1/0/0) [Jun 3 15:33:07] DEBUG[1483] rtp.c: Channel 'Zap/117-1' has no RTP, not doing anything [Jun 3 15:33:07] DEBUG[1483] app_dial.c: Exiting with DIALSTATUS=BUSY. [Jun 3 15:33:07] DEBUG[1483] app_macro.c: Executed application: Dial [Jun 3 15:33:07] DEBUG[1483] pbx.c: Launching 'Hangup' [Jun 3 15:33:07] VERBOSE[1483] logger.c: -- Executing [7329422283@default:2] Hangup("Zap/117-1", "") in new stack [Jun 3 15:33:07] DEBUG[1483] pbx.c: Spawn extension (default,7329422283,2) exited non-zero on 'Zap/117-1' [Jun 3 15:33:07] VERBOSE[1483] logger.c: == Spawn extension (default, 7329422283, 2) exited non-zero on 'Zap/117-1' [Jun 3 15:33:07] DEBUG[1483] channel.c: Soft-Hanging up channel 'Zap/117-1' [Jun 3 15:33:07] DEBUG[1483] channel.c: Hanging up channel 'Zap/117-1' [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: zt_hangup(Zap/117-1) [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/117-1 [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: Hangup: channel: 117 index = 0, normal = 102, callwait = -1, thirdcall = -1 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-09270d58 - state 4 (Invalid) [Jun 3 15:33:07] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: disabled echo cancellation on channel 117 [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/117-1 [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: Updated conferencing on 117, with 0 conference users [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/117-1 [Jun 3 15:33:07] DEBUG[1483] chan_zap.c: disabled echo cancellation on channel 117 [Jun 3 15:33:07] VERBOSE[1483] logger.c: -- Hungup 'Zap/117-1' [Jun 3 15:33:07] DEBUG[1483] devicestate.c: Notification of state change to be queued on device/channel Zap/117-1 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/117-1 - state 0 (Unknown) [Jun 3 15:33:07] DEBUG[1483] devicestate.c: Notification of state change to be queued on device/channel Zap/117 [Jun 3 15:33:07] DEBUG[2801] devicestate.c: Changing state for Zap/117 - state 0 (Unknown) [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '8484481955' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '8484481955' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '7329422283' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is 'Zap/117-1' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is 'SIP/fsa-mg2-09270d58' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '2008-06-03 15:33:07' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '2008-06-03 15:33:07' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '0' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '0' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is 'BUSY' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is 'mg3-1212521587.40458' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '' [Jun 3 15:33:07] DEBUG[1483] pbx.c: Function result is '' [Jun 3 15:33:07] VERBOSE[2812] logger.c: Really destroying SIP dialog '6c2319050d7565b4534d8aff52df8250@64.19.145.7' Method: INVITE [Jun 3 15:33:07] DEBUG[1192] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:07] DEBUG[1471] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 64.19.145.4:15979 [Jun 3 15:33:07] DEBUG[1471] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:08] DEBUG[1111] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1183] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[31967] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1464] chan_zap.c: DTMF digit: 0 on Zap/66-1 [Jun 3 15:33:08] DEBUG[1464] channel.c: Set channel SIP/fsa-mg2-090c2ed0 to write format slin [Jun 3 15:33:08] DEBUG[1464] channel.c: Scheduling timer at 160 sample intervals [Jun 3 15:33:08] DEBUG[1464] channel.c: Generator got voice, switching to phase locked mode [Jun 3 15:33:08] DEBUG[1464] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:08] DEBUG[1472] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 64.19.145.4:15961 [Jun 3 15:33:08] DEBUG[1472] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:08] DEBUG[1070] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[32070] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1464] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 64.19.145.4:19081 [Jun 3 15:33:08] DEBUG[1464] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:08] DEBUG[1464] channel.c: Set channel SIP/fsa-mg2-090c2ed0 to write format ulaw [Jun 3 15:33:08] DEBUG[1464] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:08] DEBUG[1464] channel.c: Thread 58997664 Blocking 'SIP/fsa-mg2-090c2ed0', already blocked by thread 58997664 in procedure ast_write [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:7328406462@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK09cb08d5;rport^M From: ;tag=as2d527050^M To: "7328406462" ;tag=as74cbbd20^M Contact: ^M Call-ID: 12fc620851de50b446d0113353e78906@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25458 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 17228 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:08] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:08] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:08] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:17228 [Jun 3 15:33:08] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-092c7fd8 [Jun 3 15:33:08] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:17228 [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 12fc620851de50b446d0113353e78906@64.19.145.7 [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-092c7fd8: This call is UP.... [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK09cb08d5;received=64.19.145.4;rport=5060^M From: ;tag=as2d527050^M To: "7328406462" ;tag=as74cbbd20^M Call-ID: 12fc620851de50b446d0113353e78906@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 13726 [Jun 3 15:33:08] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK09cb08d5;received=64.19.145.4;rport=5060^M From: ;tag=as2d527050^M To: "7328406462" ;tag=as74cbbd20^M Call-ID: 12fc620851de50b446d0113353e78906@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2760 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13726 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:7328406462@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK15554922;rport^M From: ;tag=as2d527050^M To: "7328406462" ;tag=as74cbbd20^M Contact: ^M Call-ID: 12fc620851de50b446d0113353e78906@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:08] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Stopping retransmission on '12fc620851de50b446d0113353e78906@64.19.145.7' of Response 103: Match Found [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> BYE sip:7328406462@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4c7a05bf;rport^M From: ;tag=as2d527050^M To: "7328406462" ;tag=as74cbbd20^M Call-ID: 12fc620851de50b446d0113353e78906@64.19.145.7^M CSeq: 104 BYE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:08] VERBOSE[2812] logger.c: --- (9 headers 0 lines) --- [Jun 3 15:33:08] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Setting SIP_ALREADYGONE on dialog 12fc620851de50b446d0113353e78906@64.19.145.7 [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Received bye, issuing owner hangup [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4c7a05bf;received=64.19.145.4;rport=5060^M From: ;tag=as2d527050^M To: "7328406462" ;tag=as74cbbd20^M Call-ID: 12fc620851de50b446d0113353e78906@64.19.145.7^M CSeq: 104 BYE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:08] DEBUG[1133] channel.c: Didn't get a frame from channel: SIP/fsa-mg2-092c7fd8 [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Requested indication 20 on channel Zap/38-1 [Jun 3 15:33:08] DEBUG[1133] channel.c: Bridge stops bridging channels Zap/38-1 and SIP/fsa-mg2-092c7fd8 [Jun 3 15:33:08] DEBUG[1133] channel.c: Hanging up channel 'SIP/fsa-mg2-092c7fd8' [Jun 3 15:33:08] DEBUG[1133] chan_sip.c: Hangup call SIP/fsa-mg2-092c7fd8, SIP callid 12fc620851de50b446d0113353e78906@64.19.145.7) [Jun 3 15:33:08] DEBUG[1133] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-092c7fd8 [Jun 3 15:33:08] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-092c7fd8 [Jun 3 15:33:08] DEBUG[1133] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:08] DEBUG[1133] rtp.c: Channel 'Zap/38-1' has no RTP, not doing anything [Jun 3 15:33:08] DEBUG[1133] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 3 15:33:08] DEBUG[1133] app_macro.c: Spawn extension (macro-MTTDial,s,1) exited non-zero on 'Zap/38-1' in macro 'MTTDial' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Spawn extension (macro-MTTDial,s,1) exited non-zero on 'Zap/38-1' [Jun 3 15:33:08] VERBOSE[1133] logger.c: == Spawn extension (macro-MTTDial, s, 1) exited non-zero on 'Zap/38-1' [Jun 3 15:33:08] DEBUG[1133] channel.c: Soft-Hanging up channel 'Zap/38-1' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Launching 'Macro' [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Executing [h@macro-MTTDial:1] Macro("Zap/38-1", "writesavedsipcallid") in new stack [Jun 3 15:33:08] DEBUG[1133] pbx.c: Expression result is '0' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Expression result is '2' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Launching 'GotoIf' [Jun 3 15:33:08] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-092c7fd8 - state 4 (Invalid) [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Executing [s@macro-writesavedsipcallid:1] GotoIf("Zap/38-1", "0?DONE:2") in new stack [Jun 3 15:33:08] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Goto (macro-writesavedsipcallid,s,2) [Jun 3 15:33:08] DEBUG[1133] app_macro.c: Executed application: GotoIf [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '12fc620851de50b446d0113353e78906@64.19.145.7' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Launching 'Set' [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Executing [s@macro-writesavedsipcallid:2] Set("Zap/38-1", "CDR(SIPCALLID2)=12fc620851de50b446d0113353e78906@64.19.145.7") in new stack [Jun 3 15:33:08] DEBUG[1133] app_macro.c: Executed application: Set [Jun 3 15:33:08] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Really destroying SIP dialog '12fc620851de50b446d0113353e78906@64.19.145.7' Method: BYE [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '12fc620851de50b446d0113353e78906@64.19.145.7' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Launching 'NoOp' [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Executing [s@macro-writesavedsipcallid:3] NoOp("Zap/38-1", "12fc620851de50b446d0113353e78906@64.19.145.7") in new stack [Jun 3 15:33:08] DEBUG[1133] app_macro.c: Executed application: Noop [Jun 3 15:33:08] DEBUG[1133] pbx.c: Launching 'NoOp' [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Executing [s@macro-writesavedsipcallid:4] NoOp("Zap/38-1", "ANSWER") in new stack [Jun 3 15:33:08] DEBUG[1133] app_macro.c: Executed application: Noop [Jun 3 15:33:08] DEBUG[1133] channel.c: Hanging up channel 'Zap/38-1' [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: zt_hangup(Zap/38-1) [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/38-1 [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Hangup: channel: 38 index = 0, normal = 47, callwait = -1, thirdcall = -1 [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: disabled echo cancellation on channel 38 [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/38-1 [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Updated conferencing on 38, with 0 conference users [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/38-1 [Jun 3 15:33:08] DEBUG[1133] chan_zap.c: disabled echo cancellation on channel 38 [Jun 3 15:33:08] VERBOSE[1133] logger.c: -- Hungup 'Zap/38-1' [Jun 3 15:33:08] DEBUG[1133] devicestate.c: Notification of state change to be queued on device/channel Zap/38-1 [Jun 3 15:33:08] DEBUG[1133] devicestate.c: Notification of state change to be queued on device/channel Zap/38 [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '7328406462' [Jun 3 15:33:08] DEBUG[2801] devicestate.c: Changing state for Zap/38-1 - state 0 (Unknown) [Jun 3 15:33:08] DEBUG[2801] devicestate.c: Changing state for Zap/38 - state 0 (Unknown) [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '7328406462' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '7323642856' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is 'Zap/38-1' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is 'SIP/fsa-mg2-092c7fd8' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '2008-06-03 15:31:31' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '2008-06-03 15:31:36' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '2008-06-03 15:33:08' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '97' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '92' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is 'ANSWERED' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is 'mg3-1212521491.40300' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '' [Jun 3 15:33:08] DEBUG[1133] pbx.c: Function result is '12fc620851de50b446d0113353e78906@64.19.145.7' [Jun 3 15:33:08] DEBUG[1107] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1080] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1097] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1100] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1022] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1187] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1185] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1138] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1006] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[648] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1464] chan_zap.c: DTMF digit: 4 on Zap/66-1 [Jun 3 15:33:08] DEBUG[1464] channel.c: Set channel SIP/fsa-mg2-090c2ed0 to write format slin [Jun 3 15:33:08] DEBUG[1464] channel.c: Scheduling timer at 160 sample intervals [Jun 3 15:33:08] DEBUG[1464] channel.c: Generator got voice, switching to phase locked mode [Jun 3 15:33:08] DEBUG[1464] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:08] DEBUG[1090] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[484] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1172] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1100] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 40 [Jun 3 15:33:08] DEBUG[1190] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 101 [Jun 3 15:33:08] DEBUG[1180] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 42 [Jun 3 15:33:08] DEBUG[1123] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 70 [Jun 3 15:33:08] DEBUG[520] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 134 [Jun 3 15:33:08] DEBUG[1100] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 40 [Jun 3 15:33:08] DEBUG[1180] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 42 [Jun 3 15:33:08] DEBUG[1190] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 101 [Jun 3 15:33:08] DEBUG[1464] channel.c: Set channel SIP/fsa-mg2-090c2ed0 to write format ulaw [Jun 3 15:33:08] DEBUG[1464] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:08] DEBUG[1464] channel.c: Thread 58997664 Blocking 'SIP/fsa-mg2-090c2ed0', already blocked by thread 58997664 in procedure ast_write [Jun 3 15:33:08] DEBUG[1161] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] DEBUG[1188] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:08] VERBOSE[2822] logger.c: -- Accepting call from '7323493030' to '9085617300' on channel 1/14, span 1 [Jun 3 15:33:08] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 38 [Jun 3 15:33:08] DEBUG[1484] pbx.c: Launching 'Macro' [Jun 3 15:33:08] VERBOSE[1484] logger.c: -- Executing [9085617300@default:1] Macro("Zap/38-1", "MTTDial|SIP/9085617300@fsa-mg2") in new stack [Jun 3 15:33:08] DEBUG[1484] pbx.c: Launching 'Dial' [Jun 3 15:33:08] VERBOSE[1484] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/38-1", "SIP/9085617300@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:08] DEBUG[1484] rtp.c: Channel 'Zap/38-1' has no RTP, not doing anything [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable ARG1. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable ANI2. [Jun 3 15:33:08] DEBUG[1484] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Outgoing Call for 9085617300 [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[1484] logger.c: Audio is at 64.19.145.7 port 13914 [Jun 3 15:33:08] VERBOSE[1484] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:08] DEBUG[1484] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[1484] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9085617300@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1d91c80e;rport^M From: "7323493030" ;tag=as51ddbc06^M To: ^M Contact: ^M Call-ID: 322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:08 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13914 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:08] VERBOSE[1484] logger.c: -- Called 9085617300@fsa-mg2 [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1d91c80e;received=64.19.145.7;rport=5060^M From: "7323493030" ;tag=as51ddbc06^M To: ;tag=as1eec6e17^M Call-ID: 322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2cb9c0b2"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:08] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Stopping retransmission on '322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:08] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9085617300@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1d91c80e;rport^M From: "7323493030" ;tag=as51ddbc06^M To: ;tag=as1eec6e17^M Contact: ^M Call-ID: 322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 13914 [Jun 3 15:33:08] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:08] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:9085617300@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7e8223be;rport^M From: "7323493030" ;tag=as51ddbc06^M To: ^M Contact: ^M Call-ID: 322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:9085617300@64.19.145.4", nonce="2cb9c0b2", response="fa31c95444a3d2f3d561bd07fd40a63c"^M Date: Tue, 03 Jun 2008 19:33:08 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 13914 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:08] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7e8223be;received=64.19.145.7;rport=5060^M From: "7323493030" ;tag=as51ddbc06^M To: ^M Call-ID: 322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:08] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:08] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7' Request 103: Found [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7e8223be;received=64.19.145.7;rport=5060^M From: "7323493030" ;tag=as51ddbc06^M To: ;tag=as7d7048c5^M Call-ID: 322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '322279ae7ad9c48158f8dd0c03beb5f0@64.19.145.7' Request 103: Found [Jun 3 15:33:09] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-092c7fd8 [Jun 3 15:33:09] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-092c7fd8 [Jun 3 15:33:09] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:09] VERBOSE[1484] logger.c: -- SIP/fsa-mg2-092c7fd8 is ringing [Jun 3 15:33:09] DEBUG[1484] rtp.c: Channel 'Zap/38-1' has no RTP, not doing anything [Jun 3 15:33:09] DEBUG[1484] chan_zap.c: Requested indication 3 on channel Zap/38-1 [Jun 3 15:33:09] DEBUG[1484] devicestate.c: Notification of state change to be queued on device/channel Zap/38-1 [Jun 3 15:33:09] DEBUG[1484] devicestate.c: Notification of state change to be queued on device/channel Zap/38 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-092c7fd8 - state 4 (Invalid) [Jun 3 15:33:09] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for Zap/38-1 - state 0 (Unknown) [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for Zap/38 - state 6 (Ringing) [Jun 3 15:33:09] DEBUG[1074] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[594] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1157] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1153] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1191] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1126] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1046] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1011] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 49 [Jun 3 15:33:09] DEBUG[31970] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1174] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] VERBOSE[2822] logger.c: -- Accepting call from '6103066597' to '7322518000' on channel 3/21, span 1 [Jun 3 15:33:09] DEBUG[1485] pbx.c: Launching 'Macro' [Jun 3 15:33:09] DEBUG[2822] chan_zap.c: Enabled echo cancellation on channel 117 [Jun 3 15:33:09] VERBOSE[1485] logger.c: -- Executing [7322518000@default:1] Macro("Zap/117-1", "MTTDial|SIP/7322518000@fsa-mg2") in new stack [Jun 3 15:33:09] DEBUG[1485] pbx.c: Launching 'Dial' [Jun 3 15:33:09] VERBOSE[1485] logger.c: -- Executing [s@macro-MTTDial:1] Dial("Zap/117-1", "SIP/7322518000@fsa-mg2||M(savesipcallid)") in new stack [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Setting NAT on RTP to On [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: This channel will not be able to handle video. [Jun 3 15:33:09] DEBUG[1485] rtp.c: Channel 'Zap/117-1' has no RTP, not doing anything [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable MACRO_DEPTH. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable ARG1. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable MACRO_PRIORITY. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable MACRO_CONTEXT. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable MACRO_EXTEN. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable CALLEDTON. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable ANI2. [Jun 3 15:33:09] DEBUG[1485] channel.c: Not copying variable TRANSFERCAPABILITY. [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Outgoing Call for 7322518000 [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[1485] logger.c: Audio is at 64.19.145.7 port 12110 [Jun 3 15:33:09] VERBOSE[1485] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:09] DEBUG[1485] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[1485] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7322518000@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK377a27f2;rport^M From: "6103066597" ;tag=as7977c8ce^M To: ^M Contact: ^M Call-ID: 306079776a4e79135b0288aa2780910a@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Date: Tue, 03 Jun 2008 19:33:09 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2757 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 12110 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:09] VERBOSE[1485] logger.c: -- Called 7322518000@fsa-mg2 [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 407 Proxy Authentication Required^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK377a27f2;received=64.19.145.7;rport=5060^M From: "6103066597" ;tag=as7977c8ce^M To: ;tag=as52a7fe95^M Call-ID: 306079776a4e79135b0288aa2780910a@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="61ef7a42"^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Acked pending invite 102 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Stopping retransmission on '306079776a4e79135b0288aa2780910a@64.19.145.7' of Request 102: Match Found [Jun 3 15:33:09] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7322518000@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK377a27f2;rport^M From: "6103066597" ;tag=as7977c8ce^M To: ;tag=as52a7fe95^M Contact: ^M Call-ID: 306079776a4e79135b0288aa2780910a@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Auth attempt 1 on INVITE [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 12110 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Reliably Transmitting (NAT) to 64.19.145.4:5060: INVITE sip:7322518000@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6e0e3c4a;rport^M From: "6103066597" ;tag=as7977c8ce^M To: ^M Contact: ^M Call-ID: 306079776a4e79135b0288aa2780910a@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Proxy-Authorization: Digest username="mg2", realm="asterisk", algorithm=MD5, uri="sip:7322518000@64.19.145.4", nonce="61ef7a42", response="05229dbba1d3c835ec4815a0444d9401"^M Date: Tue, 03 Jun 2008 19:33:09 GMT^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2758 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 12110 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M --- [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6e0e3c4a;received=64.19.145.7;rport=5060^M From: "6103066597" ;tag=as7977c8ce^M To: ^M Call-ID: 306079776a4e79135b0288aa2780910a@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '306079776a4e79135b0288aa2780910a@64.19.145.7' Request 103: Found [Jun 3 15:33:09] DEBUG[1173] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7ab3e8e4;received=64.19.145.7;rport=5060^M From: "7329221000" ;tag=as17e91bed^M To: ;tag=as47fb5211^M Call-ID: 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 17638 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Stopping retransmission on '5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:09] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:17638 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-09281540 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:17638 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:09] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Strict routing enforced for session 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7 [Jun 3 15:33:09] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:09] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:7325301500@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK790080b2;rport^M From: "7329221000" ;tag=as17e91bed^M To: ;tag=as47fb5211^M Contact: ^M Call-ID: 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:09] DEBUG[1474] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-09281540 [Jun 3 15:33:09] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-09281540 [Jun 3 15:33:09] DEBUG[1474] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:09] VERBOSE[1474] logger.c: -- SIP/fsa-mg2-09281540 answered Zap/41-1 [Jun 3 15:33:09] DEBUG[1474] rtp.c: Channel 'Zap/41-1' has no RTP, not doing anything [Jun 3 15:33:09] DEBUG[1474] pbx.c: Launching 'Set' Jun 3 15:33:09] VERBOSE[1474] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-09281540", "DB(CHANID/fsa-mg2-09281540)=5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7") in new stack [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:7329221000@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4a1201cc;rport^M From: ;tag=as47fb5211^M To: "7329221000" ;tag=as17e91bed^M Contact: ^M Call-ID: 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.62.203^M s=session^M c=IN IP4 209.191.62.203^M t=0 0^M m=audio 10002 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:09] VERBOSE[2812] logger.c: Sending to 64.19.145.4 : 5060 (NAT) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.62.203:10002 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-09281540 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Peer audio RTP is at port 209.191.62.203:10002 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Got a SIP re-invite for call 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7 [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: SIP/fsa-mg2-09281540: This call is UP.... [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-09281540 - state 4 (Invalid) [Jun 3 15:33:09] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 100 Trying^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4a1201cc;received=64.19.145.4;rport=5060^M From: ;tag=as47fb5211^M To: "7329221000" ;tag=as17e91bed^M Call-ID: 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <------------> [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Setting framing from config on incoming call [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[2812] logger.c: Audio is at 64.19.145.7 port 17232 [Jun 3 15:33:09] VERBOSE[2812] logger.c: Adding codec 0x4 (ulaw) to SDP [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: -- Done with adding codecs to SDP [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- Reliably Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK4a1201cc;received=64.19.145.4;rport=5060^M From: ;tag=as47fb5211^M To: "7329221000" ;tag=as17e91bed^M Call-ID: 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 180^M ^M v=0^M o=root 2757 2759 IN IP4 64.19.145.7^M s=session^M c=IN IP4 64.19.145.7^M t=0 0^M m=audio 17232 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:7329221000@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK014cdcff;rport^M From: ;tag=as47fb5211^M To: "7329221000" ;tag=as17e91bed^M Contact: ^M Call-ID: 5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: Stopping retransmission on '5b2ae2007e619f3743670c2f1e369b5f@64.19.145.7' of Response 102: Match Found [Jun 3 15:33:09] DEBUG[1474] app_macro.c: Executed application: Set [Jun 3 15:33:09] DEBUG[1474] app_dial.c: Macro exited with status 0 [Jun 3 15:33:09] DEBUG[1474] chan_zap.c: Requested indication -1 on channel Zap/41-1 [Jun 3 15:33:09] DEBUG[1474] devicestate.c: Notification of state change to be queued on device/channel Zap/41-1 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for Zap/41-1 - state 0 (Unknown) [Jun 3 15:33:09] DEBUG[1474] devicestate.c: Notification of state change to be queued on device/channel Zap/41 [Jun 3 15:33:09] DEBUG[1474] chan_zap.c: Requested indication 20 on channel Zap/41-1 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for Zap/41 - state 2 (In use) [Jun 3 15:33:09] DEBUG[1148] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1474] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:09] DEBUG[1474] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:09] DEBUG[1193] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1474] rtp.c: RTP NAT: Got audio from other end. Now sending to address 64.19.145.4:17638 [Jun 3 15:33:09] DEBUG[1466] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1460] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1474] rtp.c: RTP NAT: Got audio from other end. Now sending to address 209.191.62.203:10002 [Jun 3 15:33:09] DEBUG[1180] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1011] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:09] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 180 Ringing^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK6e0e3c4a;received=64.19.145.7;rport=5060^M From: "6103066597" ;tag=as7977c8ce^M To: ;tag=as5937e2e6^M Call-ID: 306079776a4e79135b0288aa2780910a@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:09] VERBOSE[2812] logger.c: --- (11 headers 0 lines) --- [Jun 3 15:33:09] DEBUG[2812] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '306079776a4e79135b0288aa2780910a@64.19.145.7' Request 103: Found [Jun 3 15:33:09] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-0933e1a0 [Jun 3 15:33:09] DEBUG[2812] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:09] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-0933e1a0 [Jun 3 15:33:09] VERBOSE[1485] logger.c: -- SIP/fsa-mg2-0933e1a0 is ringing [Jun 3 15:33:09] DEBUG[1485] rtp.c: Channel 'Zap/117-1' has no RTP, not doing anything [Jun 3 15:33:09] DEBUG[1485] chan_zap.c: Requested indication 3 on channel Zap/117-1 [Jun 3 15:33:09] DEBUG[1485] devicestate.c: Notification of state change to be queued on device/channel Zap/117-1 [Jun 3 15:33:09] DEBUG[1485] devicestate.c: Notification of state change to be queued on device/channel Zap/117 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-0933e1a0 - state 4 (Invalid) [Jun 3 15:33:09] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for Zap/117-1 - state 0 (Unknown) [Jun 3 15:33:09] DEBUG[2801] devicestate.c: Changing state for Zap/117 - state 6 (Ringing) [Jun 3 15:33:09] DEBUG[599] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:09] DEBUG[1092] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[663] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK1ff8825c;received=64.19.145.7;rport=5060^M From: "9733953226" ;tag=as6ced9960^M To: ;tag=as49a1789e^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 18488 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Stopping retransmission on '098a79882bcf4927036b426a2503e8ce@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:10] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:18488 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-08f77900 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:10] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:10] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:18488 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:10] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Strict routing enforced for session 098a79882bcf4927036b426a2503e8ce@64.19.145.7 [Jun 3 15:33:10] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:10] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:2017849880@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK5c2998bd;rport^M From: "9733953226" ;tag=as6ced9960^M To: ;tag=as49a1789e^M Contact: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:9733953226@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK367b7c4c;rport^M From: ;tag=as49a1789e^M To: "9733953226" ;tag=as6ced9960^M Contact: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.63.161^M s=session^M c=IN IP4 209.191.63.161^M t=0 0^M m=audio 10000 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 482 Loop Detected^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK367b7c4c;received=64.19.145.4;rport=5060^M From: ;tag=as49a1789e^M To: "9733953226" ;tag=as6ced9960^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Length: 0^M X-Asterisk-HangupCause: Normal Clearing^M X-Asterisk-HangupCauseCode: 16^M ^M <------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: Scheduling destruction of SIP dialog '098a79882bcf4927036b426a2503e8ce@64.19.145.7' in 32000 ms (Method: INVITE) [Jun 3 15:33:10] DEBUG[1477] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-08f77900 [Jun 3 15:33:10] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-08f77900 [Jun 3 15:33:10] DEBUG[1477] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:10] VERBOSE[1477] logger.c: -- SIP/fsa-mg2-08f77900 answered Zap/113-1 [Jun 3 15:33:10] DEBUG[1477] rtp.c: Channel 'Zap/113-1' has no RTP, not doing anything [Jun 3 15:33:10] DEBUG[1477] pbx.c: Launching 'Set' [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-08f77900 - state 4 (Invalid) [Jun 3 15:33:10] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:10] VERBOSE[1477] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-08f77900", "DB(CHANID/fsa-mg2-08f77900)=098a79882bcf4927036b426a2503e8ce@64.19.145.7") in new stack [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:9733953226@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK367b7c4c;rport^M From: ;tag=as49a1789e^M To: "9733953226" ;tag=as6ced9960^M Contact: ^M Call-ID: 098a79882bcf4927036b426a2503e8ce@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:10] DEBUG[1477] app_macro.c: Executed application: Set [Jun 3 15:33:10] DEBUG[1477] app_dial.c: Macro exited with status 0 [Jun 3 15:33:10] DEBUG[1477] chan_zap.c: Requested indication -1 on channel Zap/113-1 [Jun 3 15:33:10] DEBUG[1477] devicestate.c: Notification of state change to be queued on device/channel Zap/113-1 [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for Zap/113-1 - state 0 (Unknown) [Jun 3 15:33:10] DEBUG[1477] devicestate.c: Notification of state change to be queued on device/channel Zap/113 [Jun 3 15:33:10] DEBUG[2801] channel.c: Avoiding initial deadlock for channel '0x8f76e30' [Jun 3 15:33:10] DEBUG[1477] chan_zap.c: Requested indication 20 on channel Zap/113-1 [Jun 3 15:33:10] DEBUG[1477] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:10] DEBUG[1477] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for Zap/113 - state 2 (In use) [Jun 3 15:33:10] DEBUG[972] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1469] chan_zap.c: DTMF digit: 6 on Zap/108-1 [Jun 3 15:33:10] DEBUG[1469] channel.c: Set channel SIP/fsa-mg2-09173840 to write format slin [Jun 3 15:33:10] DEBUG[1469] channel.c: Scheduling timer at 160 sample intervals [Jun 3 15:33:10] DEBUG[1159] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1469] channel.c: Generator got voice, switching to phase locked mode [Jun 3 15:33:10] DEBUG[1469] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:10] DEBUG[626] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1144] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1469] channel.c: Set channel SIP/fsa-mg2-09173840 to write format ulaw [Jun 3 15:33:10] DEBUG[1469] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:10] DEBUG[1469] channel.c: Thread 13400992 Blocking 'SIP/fsa-mg2-09173840', already blocked by thread 13400992 in procedure ast_write [Jun 3 15:33:10] DEBUG[1473] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 64.19.145.4:19169 [Jun 3 15:33:10] DEBUG[1473] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:10] DEBUG[1183] chan_zap.c: DTMF digit: # on Zap/47-1 [Jun 3 15:33:10] DEBUG[1183] channel.c: Set channel SIP/fsa-mg2-09120fa0 to write format slin [Jun 3 15:33:10] DEBUG[1183] channel.c: Scheduling timer at 160 sample intervals [Jun 3 15:33:10] DEBUG[1183] channel.c: Generator got voice, switching to phase locked mode [Jun 3 15:33:10] DEBUG[1183] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:10] DEBUG[18048] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:10] DEBUG[1105] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1190] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[18493] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:10] DEBUG[1020] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1048] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1151] rtp.c: Got RTCP report of 64 bytes [Jun 3 15:33:10] DEBUG[1181] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1183] channel.c: Set channel SIP/fsa-mg2-09120fa0 to write format ulaw [Jun 3 15:33:10] DEBUG[1183] channel.c: Scheduling timer at 0 sample intervals [Jun 3 15:33:10] DEBUG[1183] channel.c: Thread 46209952 Blocking 'SIP/fsa-mg2-09120fa0', already blocked by thread 46209952 in procedure ast_write [Jun 3 15:33:10] DEBUG[1123] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1462] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[961] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK4054cfdf;received=64.19.145.7;rport=5060^M From: "6053356100" ;tag=as547ae42e^M To: ;tag=as411d0d58^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 13852 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Stopping retransmission on '573fabda55a14b1119085740373ef29f@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:10] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:13852 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-090c81d8 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:10] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:10] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:13852 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:10] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Strict routing enforced for session 573fabda55a14b1119085740373ef29f@64.19.145.7 [Jun 3 15:33:10] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:10] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9733760991@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK362ba3b5;rport^M From: "6053356100" ;tag=as547ae42e^M To: ;tag=as411d0d58^M Contact: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 103 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M --- [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> INVITE sip:6053356100@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK6b7c602b;rport^M From: ;tag=as411d0d58^M To: "6053356100" ;tag=as547ae42e^M Contact: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Type: application/sdp^M Content-Length: 188^M ^M v=0^M o=root 25456 25457 IN IP4 209.191.18.183^M s=session^M c=IN IP4 209.191.18.183^M t=0 0^M m=audio 10012 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (13 headers 10 lines) --- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Found SIP option: -replaces- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Matched SIP option: replaces [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- Transmitting (NAT) to 64.19.145.4:5060 ---> SIP/2.0 482 Loop Detected^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK6b7c602b;received=64.19.145.4;rport=5060^M From: ;tag=as411d0d58^M To: "6053356100" ;tag=as547ae42e^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 102 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Content-Length: 0^M X-Asterisk-HangupCause: Normal Clearing^M X-Asterisk-HangupCauseCode: 16^M ^M <------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: Scheduling destruction of SIP dialog '573fabda55a14b1119085740373ef29f@64.19.145.7' in 32000 ms (Method: INVITE) [Jun 3 15:33:10] DEBUG[1476] rtp.c: Ooh, format changed from unknown to ulaw [Jun 3 15:33:10] DEBUG[1476] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jun 3 15:33:10] DEBUG[1476] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2-090c81d8 [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> ACK sip:6053356100@64.19.145.7 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.4:5060;branch=z9hG4bK6b7c602b;rport^M From: ;tag=as411d0d58^M To: "6053356100" ;tag=as547ae42e^M Contact: ^M Call-ID: 573fabda55a14b1119085740373ef29f@64.19.145.7^M CSeq: 102 ACK^M User-Agent: Asterisk PBX^M Max-Forwards: 70^M Content-Length: 0^M ^M <-------------> [Jun 3 15:33:10] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2-090c81d8 [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (10 headers 0 lines) --- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 573fabda55a14b1119085740373ef29f@64.19.145.7) [Jun 3 15:33:10] DEBUG[1069] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] DEBUG[1476] devicestate.c: Notification of state change to be queued on device/channel SIP/fsa-mg2 [Jun 3 15:33:10] VERBOSE[1476] logger.c: -- SIP/fsa-mg2-090c81d8 answered Zap/112-1 [Jun 3 15:33:10] DEBUG[1476] rtp.c: Channel 'Zap/112-1' has no RTP, not doing anything [Jun 3 15:33:10] DEBUG[1476] pbx.c: Launching 'Set' [Jun 3 15:33:10] VERBOSE[1476] logger.c: -- Executing [s@macro-savesipcallid:1] Set("SIP/fsa-mg2-090c81d8", "DB(CHANID/fsa-mg2-090c81d8)=573fabda55a14b1119085740373ef29f@64.19.145.7") in new stack [Jun 3 15:33:10] DEBUG[1476] app_macro.c: Executed application: Set [Jun 3 15:33:10] DEBUG[1476] app_dial.c: Macro exited with status 0 [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2-090c81d8 - state 4 (Invalid) [Jun 3 15:33:10] DEBUG[2801] chan_sip.c: Checking device state for peer fsa-mg2 [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for SIP/fsa-mg2 - state 1 (Not in use) [Jun 3 15:33:10] DEBUG[1476] chan_zap.c: Requested indication -1 on channel Zap/112-1 [Jun 3 15:33:10] DEBUG[1476] devicestate.c: Notification of state change to be queued on device/channel Zap/112-1 [Jun 3 15:33:10] DEBUG[1476] devicestate.c: Notification of state change to be queued on device/channel Zap/112 [Jun 3 15:33:10] DEBUG[1476] chan_zap.c: Requested indication 20 on channel Zap/112-1 [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for Zap/112-1 - state 0 (Unknown) [Jun 3 15:33:10] DEBUG[2801] devicestate.c: Changing state for Zap/112 - state 2 (In use) [Jun 3 15:33:10] DEBUG[1042] rtp.c: Got RTCP report of 44 bytes [Jun 3 15:33:10] VERBOSE[2812] logger.c: <--- SIP read from 64.19.145.4:5060 ---> SIP/2.0 200 OK^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK7ab1e421;received=64.19.145.7;rport=5060^M From: "7322518000" ;tag=as0349e792^M To: ;tag=as46b99df8^M Call-ID: 6c0d002e57bc8a8661f15ba620616128@64.19.145.7^M CSeq: 103 INVITE^M User-Agent: Asterisk PBX^M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M Supported: replaces^M Contact: ^M Content-Type: application/sdp^M Content-Length: 182^M ^M v=0^M o=root 25456 25456 IN IP4 64.19.145.4^M s=session^M c=IN IP4 64.19.145.4^M t=0 0^M m=audio 10820 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M a=silenceSupp:off - - - -^M a=ptime:20^M a=sendrecv^M <-------------> [Jun 3 15:33:10] VERBOSE[2812] logger.c: --- (12 headers 10 lines) --- [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Acked pending invite 103 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Stopping retransmission on '6c0d002e57bc8a8661f15ba620616128@64.19.145.7' of Request 103: Match Found [Jun 3 15:33:10] VERBOSE[2812] logger.c: Found RTP audio format 0 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:10820 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Found audio description format PCMU for ID 0 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: T38 state changed to 0 on channel SIP/fsa-mg2-090cf760 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jun 3 15:33:10] VERBOSE[2812] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jun 3 15:33:10] VERBOSE[2812] logger.c: Peer audio RTP is at port 64.19.145.4:10820 [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Updating call counter for outgoing call [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: build_route: Contact hop: [Jun 3 15:33:10] VERBOSE[2812] logger.c: list_route: hop: [Jun 3 15:33:10] DEBUG[2812] chan_sip.c: Strict routing enforced for session 6c0d002e57bc8a8661f15ba620616128@64.19.145.7 [Jun 3 15:33:10] VERBOSE[2812] logger.c: set_destination: Parsing for address/port to send to [Jun 3 15:33:10] VERBOSE[2812] logger.c: set_destination: set destination to 64.19.145.4, port 5060 [Jun 3 15:33:10] VERBOSE[2812] logger.c: Transmitting (NAT) to 64.19.145.4:5060: ACK sip:9088109381@64.19.145.4 SIP/2.0^M Via: SIP/2.0/UDP 64.19.145.7:5060;branch=z9hG4bK37ef6c7b;rport^M From: "7322518000" ;tag=as0349e792^M To: ;tag=as46b99df8^M