[Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/5-1 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/5 [Jul 15 14:51:21] VERBOSE[22946] logger.c: -- Starting simple switch on 'Zap/5-1' [Jul 15 14:51:21] DEBUG[22946] pbx.c: Launching 'Dial' [Jul 15 14:51:21] VERBOSE[22946] logger.c: -- Executing [s@from-zap:1] Dial("Zap/5-1", "SIP/sv0071iv,5") in new stack [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 5-1 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for Zap/5-1 - state 0 (Unknown) [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 5 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for Zap/5 - state 2 (In use) [Jul 15 14:51:21] VERBOSE[22946] logger.c: == Using SIP RTP CoS mark 5 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Setting NAT on RTP to Off [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jul 15 14:51:21] DEBUG[22946] acl.c: Found IP address for this socket [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: *** Our capabilities are 0x6 (gsm|ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: This channel will not be able to handle video. [Jul 15 14:51:21] DEBUG[22946] rtp.c: Channel 'Zap/5-1' has no RTP, not doing anything [Jul 15 14:51:21] DEBUG[22946] channel.c: Not copying variable TRANSFERCAPABILITY. [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Outgoing Call for [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Updating call counter for outgoing call [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: ** Our capability: 0x6 (gsm|ulaw) Video flag: False Text flag: False [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jul 15 14:51:21] VERBOSE[22946] logger.c: Audio is at 192.168.20.2 port 17142 [Jul 15 14:51:21] VERBOSE[22946] logger.c: Adding codec 0x4 (ulaw) to SDP [Jul 15 14:51:21] VERBOSE[22946] logger.c: Adding codec 0x2 (gsm) to SDP [Jul 15 14:51:21] VERBOSE[22946] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: -- Done with adding codecs to SDP [Jul 15 14:51:21] DEBUG[22946] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=85) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Done building SDP. Settling with this capability: 0x6 (gsm|ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Initializing initreq for method INVITE - callid 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 38]: INVITE sip:sv0071iv.voice:5070 SIP/2.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 29]: To: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 9 [ 35]: Date: Tue, 15 Jul 2008 18:51:21 GMT [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 13 [ 19]: Content-Length: 288 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 14 [ 0]: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 0 [ 3]: v=0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 1 [ 46]: o=root 774106389 774106389 IN IP4 192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 2 [ 26]: s=Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 5 [ 29]: m=audio 17142 RTP/AVP 0 3 101 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-16 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 10 [ 25]: a=silenceSupp:off - - - - [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 12 [ 10]: a=sendrecv [Jul 15 14:51:21] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: INVITE sip:sv0071iv.voice:5070 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport Max-Forwards: 70 From: "asterisk" ;tag=as4a358f9c To: Contact: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Date: Tue, 15 Jul 2008 18:51:21 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Type: application/sdp Content-Length: 288 v=0 o=root 774106389 774106389 IN IP4 192.168.20.2 s=Asterisk PBX 1.6.0-beta9 c=IN IP4 192.168.20.2 t=0 0 m=audio 17142 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 38]: INVITE sip:sv0071iv.voice:5070 SIP/2.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 29]: To: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 9 [ 35]: Date: Tue, 15 Jul 2008 18:51:21 GMT [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 13 [ 19]: Content-Length: 288 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 14 [ 0]: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 0 [ 3]: v=0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 1 [ 46]: o=root 774106389 774106389 IN IP4 192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 2 [ 26]: s=Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 5 [ 29]: m=audio 17142 RTP/AVP 0 3 101 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-16 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 10 [ 25]: a=silenceSupp:off - - - - [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 12 [ 10]: a=sendrecv [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Trying to put 'INVITE sip' onto TCP socket... [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 29]: TO: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 0]: [Jul 15 14:51:21] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 100 Trying FROM: "asterisk";tag=as4a358f9c TO: CSEQ: 102 INVITE CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport CONTENT-LENGTH: 0 <-------------> [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 29]: TO: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 0]: [Jul 15 14:51:21] VERBOSE[22946] logger.c: --- (7 headers 0 lines) --- [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag Our tag: as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag Our tag: as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:21] VERBOSE[22946] logger.c: -- Called sv0071iv [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag Our tag: as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' Request 102: Not Found [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: SIP response 100 to standard invite [Jul 15 14:51:21] DEBUG[22946] dsp.c: Stop state 0 with duration 0 [Jul 15 14:51:21] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:21] DEBUG[22946] dsp.c: Stop state 2 with duration 3 [Jul 15 14:51:21] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:21] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 180 Ringing FROM: "asterisk";tag=as4a358f9c TO: ;epid=439D7CD5FE;tag=8d34781a1b CSEQ: 102 INVITE CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:21] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag Our tag: as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' Request 102: Not Found [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: SIP response 180 to standard invite [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv-0543b158 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv-0543b158 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv-0543b158 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv-0543b158 - state 1 (Not in use) [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv - state 1 (Not in use) [Jul 15 14:51:21] VERBOSE[22946] logger.c: -- SIP/sv0071iv-0543b158 is ringing [Jul 15 14:51:21] DEBUG[22946] chan_zap.c: Requested indication 3 on channel Zap/5-1 [Jul 15 14:51:21] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:21] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 94]: CONTACT: ;automata [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 19]: CONTENT-LENGTH: 192 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 29]: CONTENT-TYPE: application/sdp [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 9 [ 13]: ALLOW: UPDATE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 10 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 11 [ 68]: ALLOW: Ack, Cancel, Bye,Invite,Message,Info,Service,Options,BeNotify [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:21] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as4a358f9c TO: ;epid=439D7CD5FE;tag=8d34781a1b CSEQ: 102 INVITE CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport CONTACT: ;automata CONTENT-LENGTH: 192 CONTENT-TYPE: application/sdp ALLOW: UPDATE SERVER: RTCC/3.0.0.0 ALLOW: Ack, Cancel, Bye,Invite,Message,Info,Service,Options,BeNotify v=0 o=- 0 0 IN IP4 192.168.20.3 s=Microsoft Speech Server session c=IN IP4 192.168.20.3 t=0 0 m=audio 34816 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 <-------------> [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK3d9d2f37;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 94]: CONTACT: ;automata [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 19]: CONTENT-LENGTH: 192 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 29]: CONTENT-TYPE: application/sdp [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 9 [ 13]: ALLOW: UPDATE [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 10 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 11 [ 68]: ALLOW: Ack, Cancel, Bye,Invite,Message,Info,Service,Options,BeNotify [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 0 [ 3]: v=0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 1 [ 27]: o=- 0 0 IN IP4 192.168.20.3 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 2 [ 33]: s=Microsoft Speech Server session [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.20.3 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 4 [ 5]: t=0 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 5 [ 27]: m=audio 34816 RTP/AVP 0 101 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 6 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 7 [ 15]: a=fmtp:101 0-16 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Body 8 [ 10]: a=ptime:20 [Jul 15 14:51:21] VERBOSE[22946] logger.c: --- (12 headers 9 lines) --- [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Stopping retransmission on '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' of Request 102: Match Not Found [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: SIP response 200 to standard invite [Jul 15 14:51:21] VERBOSE[22946] logger.c: Found RTP audio format 0 [Jul 15 14:51:21] VERBOSE[22946] logger.c: Found RTP audio format 101 [Jul 15 14:51:21] VERBOSE[22946] logger.c: Peer audio RTP is at port 192.168.20.3:34816 [Jul 15 14:51:21] VERBOSE[22946] logger.c: Found audio description format telephone-event for ID 101 [Jul 15 14:51:21] VERBOSE[22946] logger.c: Got unsupported a:fmtp in SDP offer [Jul 15 14:51:21] VERBOSE[22946] logger.c: Capabilities: us - 0x6 (gsm|ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Jul 15 14:51:21] VERBOSE[22946] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jul 15 14:51:21] VERBOSE[22946] logger.c: Peer audio RTP is at port 192.168.20.3:34816 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: We have an owner, now see if we need to change this call [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Updating call counter for outgoing call [Jul 15 14:51:21] VERBOSE[22946] logger.c: --- set_address_from_contact host 'sv0071iv.internal.veridian.on.ca' [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: build_route: Contact hop: ;automata [Jul 15 14:51:21] VERBOSE[22946] logger.c: list_route: hop: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Strict routing enforced for session 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:21] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:21] VERBOSE[22946] logger.c: Transmitting (no NAT) to 192.168.20.3:5070: ACK sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4762fda7;rport Max-Forwards: 70 From: "asterisk" ;tag=as4a358f9c To: ;tag=8d34781a1b Contact: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 102 ACK User-Agent: Asterisk PBX 1.6.0-beta9 Content-Length: 0 --- [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 0 [ 86]: ACK sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4762fda7;rport [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as4a358f9c [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 4 [ 44]: To: ;tag=8d34781a1b [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 7 [ 13]: CSeq: 102 ACK [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Header 10 [ 0]: [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Trying to put 'ACK sip:sv' onto TCP socket... [Jul 15 14:51:21] DEBUG[22946] channel.c: Deadlock avoided for write to channel 'SIP/sv0071iv-0543b158' [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv-0543b158 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv [Jul 15 14:51:21] VERBOSE[22946] logger.c: -- SIP/sv0071iv-0543b158 answered Zap/5-1 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/5-1 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/5 [Jul 15 14:51:21] DEBUG[22946] chan_zap.c: Took Zap/5-1 off hook [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv-0543b158 [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv-0543b158 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv-0543b158 - state 1 (Not in use) [Jul 15 14:51:21] DEBUG[22946] chan_zap.c: Enabled echo cancellation on channel 5 [Jul 15 14:51:21] DEBUG[22946] chan_zap.c: No echo training requested [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv [Jul 15 14:51:21] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv - state 1 (Not in use) [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 5-1 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for Zap/5-1 - state 0 (Unknown) [Jul 15 14:51:21] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 5 [Jul 15 14:51:21] DEBUG[22946] devicestate.c: Changing state for Zap/5 - state 2 (In use) [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Requested indication 20 on channel Zap/5-1 [Jul 15 14:51:22] DEBUG[22946] rtp.c: Ooh, format changed from unknown to ulaw [Jul 15 14:51:22] DEBUG[22946] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:22] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:22] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:22] DEBUG[22946] chan_zap.c: DTMF digit: 4 on Zap/2-1 [Jul 15 14:51:22] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:22] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:22] DEBUG[22946] rtp.c: Difference is 952, ms is 139 [Jul 15 14:51:23] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:23] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=43b758331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 56]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd2ff0de [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:23] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=43b758331 TO: ;tag=as07751f27 CSEQ: 1 REFER CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd2ff0de CONTACT: ;automata CONTENT-LENGTH: 0 REFER-TO: REFERRED-BY: USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=43b758331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 56]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd2ff0de [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:23] VERBOSE[22946] logger.c: --- (12 headers 0 lines) --- [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = Found Their Call ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 Their Tag 43b758331 Our tag: as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jul 15 14:51:23] VERBOSE[22946] logger.c: Call 5c4453990889bf207a765e427d5b5e89@192.168.20.2 got a SIP call transfer from callee: (REFER)! [Jul 15 14:51:23] VERBOSE[22946] logger.c: SIP transfer to extension 5300@from-sip by sv0071iv.voice:5070 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: SIP blind transfer: Transferer channel SIP/sv0071iv-053f8898, transferee channel Zap/1-1 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Got SIP transfer, applying to bridged peer 'Zap/1-1' [Jul 15 14:51:23] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 202 Accepted Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd2ff0de;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=43b758331 To: ;tag=as07751f27 Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 CSeq: 1 REFER User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 20]: SIP/2.0 202 Accepted [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 78]: Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd2ff0de;received=192.168.20.3 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 61]: From: ;epid=439D7CD5FE;tag=43b758331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 46]: To: ;tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 13]: CSeq: 1 REFER [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 9 [ 55]: Contact: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 11 [ 0]: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket... [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: chan1->name: SIP/sv0071iv-053f8898 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Strict routing enforced for session 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:23] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:23] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK628a6dd4;rport Max-Forwards: 70 From: "asterisk" ;tag=as07751f27 To: ;tag=43b758331 Contact: Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 CSeq: 103 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: active Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 21 SIP/2.0 183 Ringing --- [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK628a6dd4;rport [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 43]: To: ;tag=43b758331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 103 NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 10 [ 26]: Subscription-state: active [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 21 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Body 0 [ 19]: SIP/2.0 183 Ringing [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:23] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/1-1' [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Blind transfer succeeded. Telling transferer. [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Strict routing enforced for session 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:23] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:23] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK48032fc4;rport Max-Forwards: 70 From: "asterisk" ;tag=as07751f27 To: ;tag=43b758331 Contact: Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 CSeq: 104 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 16 SIP/2.0 200 Ok --- [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK48032fc4;rport [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 43]: To: ;tag=43b758331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 104 NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 10 [ 48]: Subscription-state: terminated;reason=noresource [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 16 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Body 0 [ 14]: SIP/2.0 200 Ok [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:23] DEBUG[22946] channel.c: Didn't get a frame from channel: Zap/1-1 [Jul 15 14:51:23] DEBUG[22946] channel.c: Bridge stops bridging channels Zap/1-1 and SIP/sv0071iv-053f8898 [Jul 15 14:51:23] DEBUG[22946] channel.c: Hanging up channel 'SIP/sv0071iv-053f8898' [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 5c4453990889bf207a765e427d5b5e89@192.168.20.2. [Jul 15 14:51:23] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '5c4453990889bf207a765e427d5b5e89@192.168.20.2' in 6400 ms (Method: REFER) [Jul 15 14:51:23] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv-053f8898 [Jul 15 14:51:23] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv [Jul 15 14:51:23] DEBUG[22946] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jul 15 14:51:23] DEBUG[22946] pbx.c: Spawn extension (from-sip,5300,1) exited non-zero on 'Zap/1-1' [Jul 15 14:51:23] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5300, 1) exited non-zero on 'Zap/1-1' [Jul 15 14:51:23] DEBUG[22946] pbx.c: Launching 'Flash' [Jul 15 14:51:23] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:1] Flash("Zap/1-1", "") in new stack [Jul 15 14:51:23] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv-053f8898 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv-053f8898 [Jul 15 14:51:23] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv-053f8898 - state 1 (Not in use) [Jul 15 14:51:23] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv [Jul 15 14:51:23] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv - state 1 (Not in use) [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=43b758331;epid=439D7CD5FE [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK628a6dd4;rport [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:23] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as07751f27 TO: ;tag=43b758331;epid=439D7CD5FE CSEQ: 103 NOTIFY CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK628a6dd4;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=43b758331;epid=439D7CD5FE [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK628a6dd4;rport [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:23] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = Found Their Call ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 Their Tag 43b758331 Our tag: as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=43b758331;epid=439D7CD5FE [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK48032fc4;rport [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:23] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as07751f27 TO: ;tag=43b758331;epid=439D7CD5FE CSEQ: 104 NOTIFY CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK48032fc4;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=43b758331;epid=439D7CD5FE [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK48032fc4;rport [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:23] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = No match Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: = Found Their Call ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 Their Tag 43b758331 Our tag: as07751f27 [Jul 15 14:51:23] DEBUG[22946] chan_sip.c: Stopping retransmission on '5c4453990889bf207a765e427d5b5e89@192.168.20.2' of Request 104: Match Not Found [Jul 15 14:51:24] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:24] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:24] DEBUG[22946] dsp.c: Stop state 0 with duration 158 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:24] VERBOSE[22946] logger.c: Really destroying SIP dialog '5c4453990889bf207a765e427d5b5e89@192.168.20.2' Method: REFER [Jul 15 14:51:24] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:24] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:24] DEBUG[22946] dsp.c: Stop state 2 with duration 9 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:24] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:24] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:24] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:24] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Jul 15 14:51:25] DEBUG[22946] acl.c: Found IP address for this socket [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Initializing initreq for method OPTIONS - callid 2046627237e9349e540883b171642e37@192.168.20.2 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 0 [ 39]: OPTIONS sip:sv0072iv.voice:5070 SIP/2.0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK18c88d0b;rport [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as2a35a731 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 4 [ 29]: To: [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 2046627237e9349e540883b171642e37@192.168.20.2 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 9 [ 35]: Date: Tue, 15 Jul 2008 18:51:24 GMT [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jul 15 14:51:25] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.4:5070: OPTIONS sip:sv0072iv.voice:5070 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK18c88d0b;rport Max-Forwards: 70 From: "asterisk" ;tag=as2a35a731 To: Contact: Call-ID: 2046627237e9349e540883b171642e37@192.168.20.2 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.6.0-beta9 Date: Tue, 15 Jul 2008 18:51:24 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 --- [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 0 [ 39]: OPTIONS sip:sv0072iv.voice:5070 SIP/2.0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK18c88d0b;rport [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as2a35a731 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 4 [ 29]: To: [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 2046627237e9349e540883b171642e37@192.168.20.2 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 9 [ 35]: Date: Tue, 15 Jul 2008 18:51:24 GMT [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 13 [ 0]: [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Trying to put 'OPTIONS si' onto TCP socket... [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 0 [ 30]: SIP/2.0 405 Method Not Allowed [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as2a35a731 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 2 [ 44]: TO: ;tag=dc8e133aa1 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 3 [ 17]: CSEQ: 102 OPTIONS [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 2046627237e9349e540883b171642e37@192.168.20.2 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK18c88d0b;rport [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 7 [ 13]: ALLOW: NOTIFY [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 8 [ 15]: ALLOW: BeNotify [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 9 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 10 [ 0]: [Jul 15 14:51:25] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.4:5070 ---> SIP/2.0 405 Method Not Allowed FROM: "asterisk";tag=as2a35a731 TO: ;tag=dc8e133aa1 CSEQ: 102 OPTIONS CALL-ID: 2046627237e9349e540883b171642e37@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK18c88d0b;rport CONTENT-LENGTH: 0 ALLOW: NOTIFY ALLOW: BeNotify SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 0 [ 30]: SIP/2.0 405 Method Not Allowed [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as2a35a731 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 2 [ 44]: TO: ;tag=dc8e133aa1 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 3 [ 17]: CSEQ: 102 OPTIONS [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 2046627237e9349e540883b171642e37@192.168.20.2 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK18c88d0b;rport [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 7 [ 13]: ALLOW: NOTIFY [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 8 [ 15]: ALLOW: BeNotify [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 9 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Header 10 [ 0]: [Jul 15 14:51:25] VERBOSE[22946] logger.c: --- (10 headers 0 lines) --- [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: = Found Their Call ID: 2046627237e9349e540883b171642e37@192.168.20.2 Their Tag Our tag: as2a35a731 [Jul 15 14:51:25] DEBUG[22946] chan_sip.c: Stopping retransmission on '2046627237e9349e540883b171642e37@192.168.20.2' of Request 102: Match Not Found [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:25] VERBOSE[22946] logger.c: Really destroying SIP dialog '2046627237e9349e540883b171642e37@192.168.20.2' Method: OPTIONS [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 0 with duration 252 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 5 [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 5 with duration 1 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 5 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 5 with duration 1 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:25] VERBOSE[22946] logger.c: -- Flashed channel Zap/1-1 [Jul 15 14:51:25] DEBUG[22946] pbx.c: Launching 'SendDTMF' [Jul 15 14:51:25] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:2] SendDTMF("Zap/1-1", "5300") in new stack [Jul 15 14:51:25] DEBUG[22946] chan_zap.c: Started VLDTMF digit '5' [Jul 15 14:51:25] DEBUG[22946] chan_zap.c: DTMF digit: 0 on Zap/4-1 [Jul 15 14:51:25] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '5' [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 2 with duration 8 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:25] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:25] DEBUG[22946] rtp.c: Difference is 952, ms is 139 [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:25] DEBUG[22946] chan_zap.c: Started VLDTMF digit '3' [Jul 15 14:51:25] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '3' [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:25] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=43b758331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as07751f27 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKff67e42a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=43b758331 TO: ;tag=as07751f27 CSEQ: 2 BYE CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKff67e42a CONTENT-LENGTH: 0 USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=43b758331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as07751f27 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKff67e42a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: --- (9 headers 0 lines) --- [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] acl.c: Found IP address for this socket [Jul 15 14:51:26] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKff67e42a;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=43b758331 To: ;tag=as07751f27 Call-ID: 5c4453990889bf207a765e427d5b5e89@192.168.20.2 CSeq: 2 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 48' onto TCP socket... [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: That's odd... Got a request in unknown dialog. Callid 5c4453990889bf207a765e427d5b5e89@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Invalid SIP message - rejected , no callid, len 362 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=78ca77398a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK16f8e316 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=78ca77398a TO: ;tag=as2ad3b881 CSEQ: 1 REFER CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK16f8e316 CONTACT: ;automata CONTENT-LENGTH: 0 REFER-TO: REFERRED-BY: USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=78ca77398a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK16f8e316 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: --- (12 headers 0 lines) --- [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jul 15 14:51:26] VERBOSE[22946] logger.c: Call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 got a SIP call transfer from callee: (REFER)! [Jul 15 14:51:26] VERBOSE[22946] logger.c: SIP transfer to extension 5300@from-sip by sv0071iv.voice:5070 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: SIP blind transfer: Transferer channel SIP/sv0071iv-052519f8, transferee channel Zap/2-1 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Got SIP transfer, applying to bridged peer 'Zap/2-1' [Jul 15 14:51:26] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 202 Accepted Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK16f8e316;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=78ca77398a To: ;tag=as2ad3b881 Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 CSeq: 1 REFER User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 20]: SIP/2.0 202 Accepted [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 79]: Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK16f8e316;received=192.168.20.3 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 62]: From: ;epid=439D7CD5FE;tag=78ca77398a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 46]: To: ;tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 13]: CSeq: 1 REFER [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 55]: Contact: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 11 [ 0]: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket... [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: chan1->name: SIP/sv0071iv-052519f8 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Strict routing enforced for session 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:26] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:26] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK7bf277e2;rport Max-Forwards: 70 From: "asterisk" ;tag=as2ad3b881 To: ;tag=78ca77398a Contact: Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 CSeq: 103 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: active Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 21 SIP/2.0 183 Ringing --- [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK7bf277e2;rport [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 44]: To: ;tag=78ca77398a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 103 NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 10 [ 26]: Subscription-state: active [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 21 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Body 0 [ 19]: SIP/2.0 183 Ringing [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:26] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/2-1' [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Blind transfer succeeded. Telling transferer. [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Strict routing enforced for session 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:26] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:26] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK680c5005;rport Max-Forwards: 70 From: "asterisk" ;tag=as2ad3b881 To: ;tag=78ca77398a Contact: Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 CSeq: 104 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 16 SIP/2.0 200 Ok --- [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK680c5005;rport [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 44]: To: ;tag=78ca77398a [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 104 NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 10 [ 48]: Subscription-state: terminated;reason=noresource [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 16 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Body 0 [ 14]: SIP/2.0 200 Ok [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=78ca77398a;epid=439D7CD5FE [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK7bf277e2;rport [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as2ad3b881 TO: ;tag=78ca77398a;epid=439D7CD5FE CSEQ: 103 NOTIFY CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK7bf277e2;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=78ca77398a;epid=439D7CD5FE [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK7bf277e2;rport [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 69bda1b548dc8a337cb27d91413a6883@192.168.20.2) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] channel.c: Didn't get a frame from channel: Zap/2-1 [Jul 15 14:51:26] DEBUG[22946] channel.c: Bridge stops bridging channels Zap/2-1 and SIP/sv0071iv-052519f8 [Jul 15 14:51:26] DEBUG[22946] channel.c: Hanging up channel 'SIP/sv0071iv-052519f8' [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 69bda1b548dc8a337cb27d91413a6883@192.168.20.2. [Jul 15 14:51:26] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '69bda1b548dc8a337cb27d91413a6883@192.168.20.2' in 6400 ms (Method: REFER) [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv-052519f8 [Jul 15 14:51:26] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv-052519f8 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv-052519f8 [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv-052519f8 - state 1 (Not in use) [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv [Jul 15 14:51:26] DEBUG[22946] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jul 15 14:51:26] DEBUG[22946] pbx.c: Spawn extension (from-sip,5300,1) exited non-zero on 'Zap/2-1' [Jul 15 14:51:26] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5300, 1) exited non-zero on 'Zap/2-1' [Jul 15 14:51:26] DEBUG[22946] pbx.c: Launching 'Flash' [Jul 15 14:51:26] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:1] Flash("Zap/2-1", "") in new stack [Jul 15 14:51:26] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv - state 1 (Not in use) [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=78ca77398a;epid=439D7CD5FE [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK680c5005;rport [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as2ad3b881 TO: ;tag=78ca77398a;epid=439D7CD5FE CSEQ: 104 NOTIFY CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK680c5005;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=78ca77398a;epid=439D7CD5FE [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK680c5005;rport [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:26] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: = Found Their Call ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 Their Tag 78ca77398a Our tag: as2ad3b881 [Jul 15 14:51:26] DEBUG[22946] chan_sip.c: Stopping retransmission on '69bda1b548dc8a337cb27d91413a6883@192.168.20.2' of Request 104: Match Not Found [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:26] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:26] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:26] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:26] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:26] DEBUG[22946] dsp.c: Stop state 0 with duration 42 [Jul 15 14:51:26] DEBUG[22946] dsp.c: Start state 1 [Jul 15 14:51:26] DEBUG[22946] pbx.c: Launching 'Hangup' [Jul 15 14:51:26] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:3] Hangup("Zap/1-1", "") in new stack [Jul 15 14:51:26] DEBUG[22946] pbx.c: Spawn extension (from-sip,5300,3) exited non-zero on 'Zap/1-1' [Jul 15 14:51:26] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5300, 3) exited non-zero on 'Zap/1-1' [Jul 15 14:51:26] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/1-1' [Jul 15 14:51:26] DEBUG[22946] channel.c: Hanging up channel 'Zap/1-1' [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: zt_hangup(Zap/1-1) [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Hangup: channel: 1 index = 0, normal = 13, callwait = -1, thirdcall = -1 [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Disabled echo cancellation on channel 1 [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1 [Jul 15 14:51:26] DEBUG[22946] chan_zap.c: Updated conferencing on 1, with 0 conference users [Jul 15 14:51:26] VERBOSE[22946] logger.c: -- Hungup 'Zap/1-1' [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/1-1 [Jul 15 14:51:26] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 1-1 [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Changing state for Zap/1-1 - state 0 (Unknown) [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/1 [Jul 15 14:51:26] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 1 [Jul 15 14:51:26] DEBUG[22946] devicestate.c: Changing state for Zap/1 - state 0 (Unknown) [Jul 15 14:51:26] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:26] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 0 with duration 262 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:27] VERBOSE[22946] logger.c: Really destroying SIP dialog '69bda1b548dc8a337cb27d91413a6883@192.168.20.2' Method: REFER [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 2 with duration 10 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 0 with duration 5 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:27] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:27] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:28] VERBOSE[22946] logger.c: -- Flashed channel Zap/2-1 [Jul 15 14:51:28] DEBUG[22946] pbx.c: Launching 'SendDTMF' [Jul 15 14:51:28] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:2] SendDTMF("Zap/2-1", "5300") in new stack [Jul 15 14:51:28] DEBUG[22946] chan_zap.c: Started VLDTMF digit '5' [Jul 15 14:51:28] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '5' [Jul 15 14:51:28] DEBUG[22946] dsp.c: Stop state 2 with duration 7 [Jul 15 14:51:28] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:28] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:28] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:28] DEBUG[22946] chan_zap.c: Started VLDTMF digit '3' [Jul 15 14:51:28] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '3' [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:28] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:28] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:28] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 4 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 4 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:29] DEBUG[22946] dsp.c: Stop state 0 with duration 44 [Jul 15 14:51:29] DEBUG[22946] dsp.c: Start state 1 [Jul 15 14:51:29] DEBUG[22946] pbx.c: Launching 'Hangup' [Jul 15 14:51:29] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:3] Hangup("Zap/2-1", "") in new stack [Jul 15 14:51:29] DEBUG[22946] pbx.c: Spawn extension (from-sip,5300,3) exited non-zero on 'Zap/2-1' [Jul 15 14:51:29] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5300, 3) exited non-zero on 'Zap/2-1' [Jul 15 14:51:29] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/2-1' [Jul 15 14:51:29] DEBUG[22946] channel.c: Hanging up channel 'Zap/2-1' [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: zt_hangup(Zap/2-1) [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Hangup: channel: 2 index = 0, normal = 15, callwait = -1, thirdcall = -1 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Disabled echo cancellation on channel 2 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/2-1 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Updated conferencing on 2, with 0 conference users [Jul 15 14:51:29] VERBOSE[22946] logger.c: -- Hungup 'Zap/2-1' [Jul 15 14:51:29] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/2-1 [Jul 15 14:51:29] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 2-1 [Jul 15 14:51:29] DEBUG[22946] devicestate.c: Changing state for Zap/2-1 - state 0 (Unknown) [Jul 15 14:51:29] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/2 [Jul 15 14:51:29] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 2 [Jul 15 14:51:29] DEBUG[22946] devicestate.c: Changing state for Zap/2 - state 0 (Unknown) [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:29] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: DTMF digit: 3 on Zap/3-1 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 3 [Jul 15 14:51:29] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 3 [Jul 15 14:51:30] DEBUG[22946] rtp.c: Difference is 960, ms is 140 [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:30] DEBUG[22946] dsp.c: Stop state 0 with duration 401 [Jul 15 14:51:30] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:30] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:30] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:30] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:31] DEBUG[22946] chan_zap.c: DTMF digit: 6 on Zap/5-1 [Jul 15 14:51:31] DEBUG[22946] rtp.c: Difference is 952, ms is 139 [Jul 15 14:51:31] DEBUG[22946] chan_zap.c: Write returned -1 (Resource temporarily unavailable) on channel 5 [Jul 15 14:51:31] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:31] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:31] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:31] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=78ca77398a [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as2ad3b881 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKf39e5560 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=78ca77398a TO: ;tag=as2ad3b881 CSEQ: 2 BYE CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKf39e5560 CONTENT-LENGTH: 0 USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=78ca77398a [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as2ad3b881 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKf39e5560 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: --- (9 headers 0 lines) --- [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = No match Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:31] DEBUG[22946] acl.c: Found IP address for this socket [Jul 15 14:51:31] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKf39e5560;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=78ca77398a To: ;tag=as2ad3b881 Call-ID: 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 CSeq: 2 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 48' onto TCP socket... [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: That's odd... Got a request in unknown dialog. Callid 69bda1b548dc8a337cb27d91413a6883@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Invalid SIP message - rejected , no callid, len 363 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK64a19fb4 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=8d34781a1b TO: ;tag=as4a358f9c CSEQ: 1 REFER CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK64a19fb4 CONTACT: ;automata CONTENT-LENGTH: 0 REFER-TO: REFERRED-BY: USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK64a19fb4 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: --- (12 headers 0 lines) --- [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jul 15 14:51:31] VERBOSE[22946] logger.c: Call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 got a SIP call transfer from callee: (REFER)! [Jul 15 14:51:31] VERBOSE[22946] logger.c: SIP transfer to extension 5007@from-sip by sv0071iv.voice:5070 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: SIP blind transfer: Transferer channel SIP/sv0071iv-0543b158, transferee channel Zap/5-1 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Got SIP transfer, applying to bridged peer 'Zap/5-1' [Jul 15 14:51:31] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 202 Accepted Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK64a19fb4;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=8d34781a1b To: ;tag=as4a358f9c Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 1 REFER User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 20]: SIP/2.0 202 Accepted [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 79]: Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK64a19fb4;received=192.168.20.3 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 62]: From: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 46]: To: ;tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 13]: CSeq: 1 REFER [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 55]: Contact: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 11 [ 0]: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket... [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: chan1->name: SIP/sv0071iv-0543b158 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Strict routing enforced for session 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:31] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:31] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK67773d44;rport Max-Forwards: 70 From: "asterisk" ;tag=as4a358f9c To: ;tag=8d34781a1b Contact: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 103 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: active Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 21 SIP/2.0 183 Ringing --- [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK67773d44;rport [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 44]: To: ;tag=8d34781a1b [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 103 NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 10 [ 26]: Subscription-state: active [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 21 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Body 0 [ 19]: SIP/2.0 183 Ringing [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:31] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/5-1' [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Blind transfer succeeded. Telling transferer. [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Strict routing enforced for session 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:31] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:31] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK5a3fba1b;rport Max-Forwards: 70 From: "asterisk" ;tag=as4a358f9c To: ;tag=8d34781a1b Contact: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 104 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 16 SIP/2.0 200 Ok --- [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK5a3fba1b;rport [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 44]: To: ;tag=8d34781a1b [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 104 NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 10 [ 48]: Subscription-state: terminated;reason=noresource [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 16 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Body 0 [ 14]: SIP/2.0 200 Ok [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK67773d44;rport [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as4a358f9c TO: ;tag=8d34781a1b;epid=439D7CD5FE CSEQ: 103 NOTIFY CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK67773d44;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK67773d44;rport [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2) [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK5a3fba1b;rport [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as4a358f9c TO: ;tag=8d34781a1b;epid=439D7CD5FE CSEQ: 104 NOTIFY CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK5a3fba1b;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 2 [ 60]: TO: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK5a3fba1b;rport [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:31] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Stopping retransmission on '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' of Request 104: Match Not Found [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Got OK on REFER Notify message [Jul 15 14:51:31] DEBUG[22946] channel.c: Didn't get a frame from channel: Zap/5-1 [Jul 15 14:51:31] DEBUG[22946] channel.c: Bridge stops bridging channels Zap/5-1 and SIP/sv0071iv-0543b158 [Jul 15 14:51:31] DEBUG[22946] channel.c: Hanging up channel 'SIP/sv0071iv-0543b158' [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2. [Jul 15 14:51:31] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' in 6400 ms (Method: REFER) [Jul 15 14:51:31] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv-0543b158 [Jul 15 14:51:31] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv-0543b158 [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv-0543b158 [Jul 15 14:51:31] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv-0543b158 - state 1 (Not in use) [Jul 15 14:51:31] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv [Jul 15 14:51:31] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv [Jul 15 14:51:31] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv [Jul 15 14:51:31] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv - state 1 (Not in use) [Jul 15 14:51:31] DEBUG[22946] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jul 15 14:51:31] DEBUG[22946] pbx.c: Spawn extension (from-sip,5007,1) exited non-zero on 'Zap/5-1' [Jul 15 14:51:31] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5007, 1) exited non-zero on 'Zap/5-1' [Jul 15 14:51:31] DEBUG[22946] pbx.c: Launching 'Flash' [Jul 15 14:51:31] VERBOSE[22946] logger.c: -- Executing [5007@from-sip:1] Flash("Zap/5-1", "") in new stack [Jul 15 14:51:31] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:31] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:32] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:32] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:32] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:32] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:32] DEBUG[22946] dsp.c: Stop state 0 with duration 41 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Stop state 2 with duration 8 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:32] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:32] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 56]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK7612c44 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=8d34781a1b TO: ;tag=as4a358f9c CSEQ: 2 BYE CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK7612c44 CONTENT-LENGTH: 0 USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 56]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK7612c44 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: --- (9 headers 0 lines) --- [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Initializing initreq for method BYE - callid 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:32] VERBOSE[22946] logger.c: Sending to 192.168.20.3 : 5070 (no NAT) [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Setting SIP_ALREADYGONE on dialog 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:32] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' in 6400 ms (Method: BYE) [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Received bye, no owner, selfdestruct soon. [Jul 15 14:51:32] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK7612c44;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=8d34781a1b To: ;tag=as4a358f9c Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 2 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 78]: Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bK7612c44;received=192.168.20.3 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 62]: From: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 46]: To: ;tag=as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 11]: CSeq: 2 BYE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 55]: Contact: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 11 [ 0]: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket... [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=a818ea040 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 56]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKe32e1fc [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=a818ea040 TO: ;tag=as5cba3331 CSEQ: 1 REFER CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKe32e1fc CONTACT: ;automata CONTENT-LENGTH: 0 REFER-TO: REFERRED-BY: USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 58]: REFER sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=a818ea040 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 1 REFER [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 56]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKe32e1fc [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [121]: CONTACT: ;automata [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 63]: REFER-TO: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 10 [ 38]: REFERRED-BY: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 11 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 12 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: --- (12 headers 0 lines) --- [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = Found Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jul 15 14:51:32] VERBOSE[22946] logger.c: Call 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 got a SIP call transfer from callee: (REFER)! [Jul 15 14:51:32] DEBUG[22946] dsp.c: Stop state 0 with duration 5 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:32] VERBOSE[22946] logger.c: SIP transfer to extension 5300@from-sip by sv0071iv.voice:5070 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: SIP blind transfer: Transferer channel SIP/sv0071iv-0531a428, transferee channel Zap/4-1 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Got SIP transfer, applying to bridged peer 'Zap/4-1' [Jul 15 14:51:32] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 202 Accepted Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKe32e1fc;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=a818ea040 To: ;tag=as5cba3331 Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 CSeq: 1 REFER User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 20]: SIP/2.0 202 Accepted [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 78]: Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKe32e1fc;received=192.168.20.3 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 61]: From: ;epid=439D7CD5FE;tag=a818ea040 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 46]: To: ;tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 13]: CSeq: 1 REFER [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 55]: Contact: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 11 [ 0]: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket... [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: chan1->name: SIP/sv0071iv-0531a428 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Strict routing enforced for session 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:32] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:32] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK2c138595;rport Max-Forwards: 70 From: "asterisk" ;tag=as5cba3331 To: ;tag=a818ea040 Contact: Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 CSeq: 103 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: active Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 21 SIP/2.0 183 Ringing --- [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK2c138595;rport [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 43]: To: ;tag=a818ea040 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 103 NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 10 [ 26]: Subscription-state: active [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 21 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Body 0 [ 19]: SIP/2.0 183 Ringing [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:32] DEBUG[22946] chan_zap.c: Requested indication 17 on channel Zap/4-1 [Jul 15 14:51:32] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/4-1' [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Blind transfer succeeded. Telling transferer. [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Strict routing enforced for session 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:32] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:32] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4579d340;rport Max-Forwards: 70 From: "asterisk" ;tag=as5cba3331 To: ;tag=a818ea040 Contact: Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 CSeq: 104 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta9 Event: refer;id=1 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 16 SIP/2.0 200 Ok --- [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 89]: NOTIFY sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4579d340;rport [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 43]: To: ;tag=a818ea040 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 55]: Contact: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 54]: Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 16]: CSeq: 104 NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 9 [ 17]: Event: refer;id=1 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 10 [ 48]: Subscription-state: terminated;reason=noresource [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 11 [ 41]: Content-Type: message/sipfrag;version=2.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 12 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 14 [ 18]: Content-Length: 16 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 15 [ 0]: [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Body 0 [ 14]: SIP/2.0 200 Ok [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Trying to put 'NOTIFY sip' onto TCP socket... [Jul 15 14:51:32] DEBUG[22946] channel.c: Didn't get a frame from channel: Zap/4-1 [Jul 15 14:51:32] DEBUG[22946] channel.c: Bridge stops bridging channels Zap/4-1 and SIP/sv0071iv-0531a428 [Jul 15 14:51:32] DEBUG[22946] channel.c: Hanging up channel 'SIP/sv0071iv-0531a428' [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2. [Jul 15 14:51:32] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2' in 6400 ms (Method: REFER) [Jul 15 14:51:32] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv-0531a428 [Jul 15 14:51:32] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel SIP/sv0071iv [Jul 15 14:51:32] DEBUG[22946] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jul 15 14:51:32] DEBUG[22946] pbx.c: Spawn extension (from-sip,5300,1) exited non-zero on 'Zap/4-1' [Jul 15 14:51:32] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5300, 1) exited non-zero on 'Zap/4-1' [Jul 15 14:51:32] DEBUG[22946] pbx.c: Launching 'Flash' [Jul 15 14:51:32] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:1] Flash("Zap/4-1", "") in new stack [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=a818ea040;epid=439D7CD5FE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK2c138595;rport [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as5cba3331 TO: ;tag=a818ea040;epid=439D7CD5FE CSEQ: 103 NOTIFY CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK2c138595;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=a818ea040;epid=439D7CD5FE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 103 NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK2c138595;rport [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = Found Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:32] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv-0531a428 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv-0531a428 [Jul 15 14:51:32] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv-0531a428 - state 1 (Not in use) [Jul 15 14:51:32] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for SIP - sv0071iv [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Checking device state for peer sv0071iv [Jul 15 14:51:32] DEBUG[22946] devicestate.c: Changing state for SIP/sv0071iv - state 1 (Not in use) [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=a818ea040;epid=439D7CD5FE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4579d340;rport [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 200 OK FROM: "asterisk";tag=as5cba3331 TO: ;tag=a818ea040;epid=439D7CD5FE CSEQ: 104 NOTIFY CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4579d340;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 1 [ 58]: FROM: "asterisk";tag=as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 2 [ 59]: TO: ;tag=a818ea040;epid=439D7CD5FE [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 3 [ 16]: CSEQ: 104 NOTIFY [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4579d340;rport [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:32] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: = Found Their Call ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 Their Tag a818ea040 Our tag: as5cba3331 [Jul 15 14:51:32] DEBUG[22946] chan_sip.c: Stopping retransmission on '5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2' of Request 104: Match Not Found [Jul 15 14:51:32] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:32] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:33] VERBOSE[22946] logger.c: Really destroying SIP dialog '5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2' Method: REFER [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 2 with duration 7 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 0 with duration 3 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:33] VERBOSE[22946] logger.c: -- Flashed channel Zap/5-1 [Jul 15 14:51:33] DEBUG[22946] pbx.c: Launching 'SendDTMF' [Jul 15 14:51:33] VERBOSE[22946] logger.c: -- Executing [5007@from-sip:2] SendDTMF("Zap/5-1", "5007") in new stack [Jul 15 14:51:33] DEBUG[22946] chan_zap.c: Started VLDTMF digit '5' [Jul 15 14:51:33] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '5' [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 2 with duration 10 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 0 with duration 331 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:33] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:33] DEBUG[22946] dsp.c: Stop state 2 with duration 9 [Jul 15 14:51:33] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:33] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 0 with duration 6 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:34] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 0 with duration 5 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:34] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 2 with duration 5 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 0 with duration 5 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 3 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 3 with duration 1 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 2 [Jul 15 14:51:34] DEBUG[22946] chan_zap.c: Started VLDTMF digit '7' [Jul 15 14:51:34] VERBOSE[22946] logger.c: -- Flashed channel Zap/4-1 [Jul 15 14:51:34] DEBUG[22946] pbx.c: Launching 'SendDTMF' [Jul 15 14:51:34] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:2] SendDTMF("Zap/4-1", "5300") in new stack [Jul 15 14:51:34] DEBUG[22946] chan_zap.c: Started VLDTMF digit '5' [Jul 15 14:51:34] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '7' [Jul 15 14:51:34] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '5' [Jul 15 14:51:34] DEBUG[22946] dsp.c: Stop state 2 with duration 7 [Jul 15 14:51:34] DEBUG[22946] dsp.c: Start state 0 [Jul 15 14:51:35] DEBUG[22946] pbx.c: Launching 'Hangup' [Jul 15 14:51:35] VERBOSE[22946] logger.c: -- Executing [5007@from-sip:3] Hangup("Zap/5-1", "") in new stack [Jul 15 14:51:35] DEBUG[22946] pbx.c: Spawn extension (from-sip,5007,3) exited non-zero on 'Zap/5-1' [Jul 15 14:51:35] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5007, 3) exited non-zero on 'Zap/5-1' [Jul 15 14:51:35] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/5-1' [Jul 15 14:51:35] DEBUG[22946] channel.c: Hanging up channel 'Zap/5-1' [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: zt_hangup(Zap/5-1) [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Hangup: channel: 5 index = 0, normal = 19, callwait = -1, thirdcall = -1 [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Disabled echo cancellation on channel 5 [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/5-1 [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Updated conferencing on 5, with 0 conference users [Jul 15 14:51:35] VERBOSE[22946] logger.c: -- Hungup 'Zap/5-1' [Jul 15 14:51:35] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/5-1 [Jul 15 14:51:35] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 5-1 [Jul 15 14:51:35] DEBUG[22946] devicestate.c: Changing state for Zap/5-1 - state 0 (Unknown) [Jul 15 14:51:35] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/5 [Jul 15 14:51:35] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 5 [Jul 15 14:51:35] DEBUG[22946] devicestate.c: Changing state for Zap/5 - state 0 (Unknown) [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Started VLDTMF digit '3' [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '3' [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Started VLDTMF digit '0' [Jul 15 14:51:35] DEBUG[22946] chan_zap.c: Ending VLDTMF digit '0' [Jul 15 14:51:36] DEBUG[22946] dsp.c: Stop state 0 with duration 46 [Jul 15 14:51:36] DEBUG[22946] dsp.c: Start state 1 [Jul 15 14:51:36] DEBUG[22946] pbx.c: Launching 'Hangup' [Jul 15 14:51:36] VERBOSE[22946] logger.c: -- Executing [5300@from-sip:3] Hangup("Zap/4-1", "") in new stack [Jul 15 14:51:36] DEBUG[22946] pbx.c: Spawn extension (from-sip,5300,3) exited non-zero on 'Zap/4-1' [Jul 15 14:51:36] VERBOSE[22946] logger.c: == Spawn extension (from-sip, 5300, 3) exited non-zero on 'Zap/4-1' [Jul 15 14:51:36] DEBUG[22946] channel.c: Soft-Hanging up channel 'Zap/4-1' [Jul 15 14:51:36] DEBUG[22946] channel.c: Hanging up channel 'Zap/4-1' [Jul 15 14:51:36] DEBUG[22946] chan_zap.c: zt_hangup(Zap/4-1) [Jul 15 14:51:36] DEBUG[22946] chan_zap.c: Hangup: channel: 4 index = 0, normal = 18, callwait = -1, thirdcall = -1 [Jul 15 14:51:36] DEBUG[22946] chan_zap.c: Disabled echo cancellation on channel 4 [Jul 15 14:51:36] DEBUG[22946] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/4-1 [Jul 15 14:51:36] DEBUG[22946] chan_zap.c: Updated conferencing on 4, with 0 conference users [Jul 15 14:51:36] VERBOSE[22946] logger.c: -- Hungup 'Zap/4-1' [Jul 15 14:51:36] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/4-1 [Jul 15 14:51:36] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 4-1 [Jul 15 14:51:36] DEBUG[22946] devicestate.c: Changing state for Zap/4-1 - state 0 (Unknown) [Jul 15 14:51:36] DEBUG[22946] devicestate.c: Notification of state change to be queued on device/channel Zap/4 [Jul 15 14:51:36] DEBUG[22946] devicestate.c: No provider found, checking channel drivers for Zap - 4 [Jul 15 14:51:36] DEBUG[22946] devicestate.c: Changing state for Zap/4 - state 0 (Unknown) [Jul 15 14:51:36] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:36] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:38] DEBUG[22946] rtp.c: Got RTCP report of 28 bytes [Jul 15 14:51:38] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Finally hanging up channel after transfer: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Strict routing enforced for session 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:39] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:39] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:39] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: BYE sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK0755206f;rport Max-Forwards: 70 From: ;epid=439D7CD5FE;tag=8d34781a1b To: ;tag=as4a358f9c Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 105 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Content-Length: 0 --- [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 0 [ 86]: BYE sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK0755206f;rport [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 3 [ 62]: From: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 4 [ 46]: To: ;tag=as4a358f9c [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 5 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 6 [ 13]: CSeq: 105 BYE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 7 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Trying to put 'BYE sip:sv' onto TCP socket... [Jul 15 14:51:39] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' in 6400 ms (Method: BYE) [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=a818ea040 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as5cba3331 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd975c070 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:39] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 FROM: ;epid=439D7CD5FE;tag=a818ea040 TO: ;tag=as5cba3331 CSEQ: 2 BYE CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd975c070 CONTENT-LENGTH: 0 USER-AGENT: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 0 [ 56]: BYE sip:asterisk@192.168.20.2:5060;transport=TCP SIP/2.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 1 [ 61]: FROM: ;epid=439D7CD5FE;tag=a818ea040 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as5cba3331 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 3 [ 11]: CSEQ: 2 BYE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 5 [ 16]: MAX-FORWARDS: 70 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 6 [ 57]: VIA: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd975c070 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 8 [ 24]: USER-AGENT: RTCC/3.0.0.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:39] VERBOSE[22946] logger.c: --- (9 headers 0 lines) --- [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: = No match Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: = No match Their Call ID: 79ca4a525683f3742cdf4f0b652d4c6d@192.168.20.2 Their Tag b1ff4b25 Our tag: as22ae0f7e [Jul 15 14:51:39] DEBUG[22946] acl.c: Found IP address for this socket [Jul 15 14:51:39] VERBOSE[22946] logger.c: <--- Transmitting (no NAT) to 192.168.20.3:5070 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/TCP 192.168.20.3:5070;branch=z9hG4bKd975c070;received=192.168.20.3 From: ;epid=439D7CD5FE;tag=a818ea040 To: ;tag=as5cba3331 Call-ID: 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 CSeq: 2 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Trying to put 'SIP/2.0 48' onto TCP socket... [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: That's odd... Got a request in unknown dialog. Callid 5585c5ff1d44c9d55a709b9e296507b1@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Invalid SIP message - rejected , no callid, len 362 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 0 [ 47]: SIP/2.0 481 Call Leg/Transaction Does Not Exist [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 105 BYE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK0755206f;rport [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:39] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 481 Call Leg/Transaction Does Not Exist FROM: ;tag=8d34781a1b;epid=439D7CD5FE TO: ;tag=as4a358f9c CSEQ: 105 BYE CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK0755206f;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 0 [ 47]: SIP/2.0 481 Call Leg/Transaction Does Not Exist [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 105 BYE [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK0755206f;rport [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:39] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag 8d34781a1b Our tag: as4a358f9c [Jul 15 14:51:39] DEBUG[22946] chan_sip.c: Stopping retransmission on '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' of Request 105: Match Not Found [Jul 15 14:51:39] WARNING[22946] chan_sip.c: Remote host can't match request BYE to call '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2'. Giving up. [Jul 15 14:51:41] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:45] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Finally hanging up channel after transfer: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Strict routing enforced for session 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:45] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:45] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:45] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: BYE sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK30e5ff94;rport Max-Forwards: 70 From: ;epid=439D7CD5FE;tag=8d34781a1b To: ;tag=as4a358f9c Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 106 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Content-Length: 0 --- [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 0 [ 86]: BYE sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK30e5ff94;rport [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 3 [ 62]: From: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 4 [ 46]: To: ;tag=as4a358f9c [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 5 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 6 [ 13]: CSeq: 106 BYE [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 7 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 9 [ 0]: [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Trying to put 'BYE sip:sv' onto TCP socket... [Jul 15 14:51:45] VERBOSE[22946] logger.c: Scheduling destruction of SIP dialog '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' in 6400 ms (Method: BYE) [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 0 [ 47]: SIP/2.0 481 Call Leg/Transaction Does Not Exist [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 106 BYE [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK30e5ff94;rport [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:45] VERBOSE[22946] logger.c: <--- SIP read from TCP://192.168.20.3:5070 ---> SIP/2.0 481 Call Leg/Transaction Does Not Exist FROM: ;tag=8d34781a1b;epid=439D7CD5FE TO: ;tag=as4a358f9c CSEQ: 106 BYE CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK30e5ff94;rport CONTENT-LENGTH: 0 SERVER: RTCC/3.0.0.0 <-------------> [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 0 [ 47]: SIP/2.0 481 Call Leg/Transaction Does Not Exist [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 1 [ 62]: FROM: ;tag=8d34781a1b;epid=439D7CD5FE [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 2 [ 46]: TO: ;tag=as4a358f9c [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 3 [ 13]: CSEQ: 106 BYE [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 4 [ 54]: CALL-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK30e5ff94;rport [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 7 [ 20]: SERVER: RTCC/3.0.0.0 [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Header 8 [ 0]: [Jul 15 14:51:45] VERBOSE[22946] logger.c: --- (8 headers 0 lines) --- [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: = Found Their Call ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 Their Tag as4a358f9c Our tag: as4a358f9c [Jul 15 14:51:45] DEBUG[22946] chan_sip.c: Stopping retransmission on '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2' of Request 106: Match Not Found [Jul 15 14:51:45] WARNING[22946] chan_sip.c: Remote host can't match request BYE to call '06ea5ae52302a5c501f9a874441d83c0@192.168.20.2'. Giving up. [Jul 15 14:51:50] DEBUG[22946] rtp.c: Got RTCP report of 112 bytes [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Finally hanging up channel after transfer: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Strict routing enforced for session 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:51] VERBOSE[22946] logger.c: set_destination: Parsing for address/port to send to [Jul 15 14:51:51] VERBOSE[22946] logger.c: set_destination: set destination to 192.168.20.3, port 5070 [Jul 15 14:51:51] VERBOSE[22946] logger.c: Reliably Transmitting (no NAT) to 192.168.20.3:5070: BYE sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4d99400f;rport Max-Forwards: 70 From: ;epid=439D7CD5FE;tag=8d34781a1b To: ;tag=as4a358f9c Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 CSeq: 107 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Content-Length: 0 --- [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 0 [ 86]: BYE sip:sv0071iv.internal.veridian.on.ca:5070;transport=Tcp;maddr=192.168.20.3 SIP/2.0 [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 192.168.20.2:5060;branch=z9hG4bK4d99400f;rport [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 3 [ 62]: From: ;epid=439D7CD5FE;tag=8d34781a1b [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 4 [ 46]: To: ;tag=as4a358f9c [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 5 [ 54]: Call-ID: 06ea5ae52302a5c501f9a874441d83c0@192.168.20.2 [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 6 [ 13]: CSeq: 107 BYE [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 7 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jul 15 14:51:51] DEBUG[22946] chan_sip.c: Header 9 [ 0]: