Sep 6 22:04:16 VERBOSE[5662] logger.c: Asterisk Event Logger restarted Sep 6 22:04:16 VERBOSE[5662] logger.c: Asterisk Queue Logger restarted Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Sep 6 22:04:30 DEBUG[5677] acl.c: ##### Testing 213.166.5.135 with 10.1.20.0 Sep 6 22:04:30 DEBUG[5677] acl.c: ##### Testing 213.166.5.135 with 172.28.1.0 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Target address 213.166.5.135 is not local, substituting externip Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 0: OPTIONS sip:gk.magrathea.net SIP/2.0 (36) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK2cd890a0;rport (64) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 2: From: "asterisk" ;tag=as6d41f0b3 (60) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 3: To: (26) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 4: Contact: (37) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 486d1c6409b52b5a59b6449a5874df6d@89.105.104.74 (55) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 9: Date: Wed, 06 Sep 2006 21:04:30 GMT (35) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 12: (0) Sep 6 22:04:30 VERBOSE[5677] logger.c: 12 headers, 0 lines Sep 6 22:04:30 VERBOSE[5677] logger.c: Reliably Transmitting (NAT) to 213.166.5.135:5060: OPTIONS sip:gk.magrathea.net SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK2cd890a0;rport From: "asterisk" ;tag=as6d41f0b3 To: Contact: Call-ID: 486d1c6409b52b5a59b6449a5874df6d@89.105.104.74 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:04:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- Sep 6 22:04:30 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #130 Sep 6 22:04:30 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 403 OPTIONS not supported Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK2cd890a0;rport=5060 From: "asterisk" ;tag=as6d41f0b3 To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.730d Call-ID: 486d1c6409b52b5a59b6449a5874df6d@89.105.104.74 CSeq: 102 OPTIONS Server: Sip EXpress router (0.8.99-dev (i386/linux)) Content-Length: 0 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 403 OPTIONS not supported (33) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK2cd890a0;rport=5060 (69) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 2: From: "asterisk" ;tag=as6d41f0b3 (60) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.730d (68) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 486d1c6409b52b5a59b6449a5874df6d@89.105.104.74 (55) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 6: Server: Sip EXpress router (0.8.99-dev (i386/linux)) (52) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 7: Content-Length: 0 (17) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 8: (0) Sep 6 22:04:30 VERBOSE[5677] logger.c: --- (8 headers 0 lines)Sep 6 22:04:30 VERBOSE[5677] logger.c: --- (8 headers 0 lines)--- Sep 6 22:04:30 DEBUG[5677] chan_sip.c: = Found Their Call ID: 486d1c6409b52b5a59b6449a5874df6d@89.105.104.74 Their Tag Our tag: as6d41f0b3 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #130 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Stopping retransmission on '486d1c6409b52b5a59b6449a5874df6d@89.105.104.74' of Request 102: Match Found Sep 6 22:04:30 VERBOSE[5677] logger.c: Destroying call '486d1c6409b52b5a59b6449a5874df6d@89.105.104.74' Sep 6 22:04:30 DEBUG[5682] chan_iax2.c: Peer lastms 15, historicms 15, maxms 120 Sep 6 22:04:30 VERBOSE[5713] logger.c: -- Attempting call on AGENT/2000 for 07966000000@auto_dial:1 (Retry 1) Sep 6 22:04:30 DEBUG[5666] devicestate.c: Changing state for Local/1012@local - state 2 (In use) Sep 6 22:04:30 VERBOSE[5713] logger.c: -- outgoing agentcall, to agent '2000', on 'Local/1012@local-cfd5,1' Sep 6 22:04:30 DEBUG[5714] app_queue.c: Device 'Local/1012@local' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:30 DEBUG[5713] channel.c: Not copying variable project. Sep 6 22:04:30 DEBUG[5713] channel.c: Not copying variable person. Sep 6 22:04:30 DEBUG[5713] channel.c: Not copying variable orgref. Sep 6 22:04:30 DEBUG[5713] channel.c: Not copying variable conref. Sep 6 22:04:30 DEBUG[5715] pbx.c: Launching 'NoCDR' Sep 6 22:04:30 VERBOSE[5715] logger.c: -- Executing NoCDR("Local/1012@local-cfd5,2", "") in new stack Sep 6 22:04:30 WARNING[5715] cdr.c: CDR on channel 'Local/1012@local-cfd5,2' not posted Sep 6 22:04:30 WARNING[5715] cdr.c: CDR on channel 'Local/1012@local-cfd5,2' lacks end Sep 6 22:04:30 DEBUG[5715] pbx.c: Expression result is '1' Sep 6 22:04:30 DEBUG[5715] pbx.c: Launching 'GotoIf' Sep 6 22:04:30 VERBOSE[5715] logger.c: -- Executing GotoIf("Local/1012@local-cfd5,2", "1?3:4") in new stack Sep 6 22:04:30 VERBOSE[5715] logger.c: -- Goto (local,1012,3) Sep 6 22:04:30 DEBUG[5715] pbx.c: Launching 'Set' Sep 6 22:04:30 VERBOSE[5715] logger.c: -- Executing Set("Local/1012@local-cfd5,2", "_ALERT_INFO=AUTODIAL") in new stack Sep 6 22:04:30 DEBUG[5715] pbx.c: Launching 'Dial' Sep 6 22:04:30 VERBOSE[5715] logger.c: -- Executing Dial("Local/1012@local-cfd5,2", "SIP/1012|500") in new stack Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Setting NAT on RTP to 0 Sep 6 22:04:30 DEBUG[5715] acl.c: ##### Testing 10.1.20.52 with 10.1.20.0 Sep 6 22:04:30 DEBUG[5715] acl.c: ##### Testing 10.1.20.52 with 172.28.1.0 Sep 6 22:04:30 DEBUG[5715] channel.c: Not copying variable STACK-local-1012-4. Sep 6 22:04:30 DEBUG[5715] channel.c: Copying soft-transferable variable ALERT_INFO. Sep 6 22:04:30 DEBUG[5715] channel.c: Not copying variable STACK-local-1012-3. Sep 6 22:04:30 DEBUG[5715] channel.c: Not copying variable STACK-local-1012-2. Sep 6 22:04:30 DEBUG[5715] channel.c: Not copying variable STACK-local-1012-1. Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Outgoing Call for 1012 Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Updating call counter for outgoing call Sep 6 22:04:30 VERBOSE[5715] logger.c: We're at 10.1.20.3 port 16064 Sep 6 22:04:30 VERBOSE[5715] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:30 VERBOSE[5715] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 0: INVITE sip:1012@10.1.20.52:5060;user=phone SIP/2.0 (50) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport (60) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as5b166e34 (67) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 3: To: (41) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 4: Contact: (36) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 5: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 9: Date: Wed, 06 Sep 2006 21:04:30 GMT (35) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 10: Alert-Info: AUTODIAL (20) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 12: Content-Type: application/sdp (29) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 13: Content-Length: 208 (19) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Header 14: (0) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: v=0 (3) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: o=root 5662 5662 IN IP4 10.1.20.3 (33) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: s=session (9) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: c=IN IP4 10.1.20.3 (18) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: m=audio 16064 RTP/AVP 8 101 (27) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: a=fmtp:101 0-16 (15) Sep 6 22:04:30 DEBUG[5715] chan_sip.c: Line: a=silenceSupp:off - - - - (25) Sep 6 22:04:30 VERBOSE[5715] logger.c: 14 headers, 10 lines Sep 6 22:04:30 VERBOSE[5715] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: INVITE sip:1012@10.1.20.52:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: Contact: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:04:30 GMT Alert-Info: AUTODIAL Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 208 v=0 o=root 5662 5662 IN IP4 10.1.20.3 s=session c=IN IP4 10.1.20.3 t=0 0 m=audio 16064 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:30 DEBUG[5715] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #133 Sep 6 22:04:30 VERBOSE[5715] logger.c: -- Called 1012 Sep 6 22:04:30 DEBUG[5715] channel.c: Set channel SIP/1012-08282898 to read format slin Sep 6 22:04:30 DEBUG[5715] channel.c: Set channel SIP/1012-08282898 to write format slin Sep 6 22:04:30 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Date: Wed, 06 Sep 2006 21:15:38 GMT CSeq: 102 INVITE Server: Cisco-CP7940G/7.5 Contact: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport (60) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as5b166e34 (67) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 3: To: (41) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:15:38 GMT (35) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 7: Server: Cisco-CP7940G/7.5 (25) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 8: Contact: (35) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 9: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE (65) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes (100) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 12: (0) Sep 6 22:04:30 VERBOSE[5677] logger.c: --- (12 headers 0 lines)Sep 6 22:04:30 VERBOSE[5677] logger.c: --- (12 headers 0 lines)--- Sep 6 22:04:30 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag Our tag: as5b166e34 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: *** SIP TIMER: Cancelling retransmission #133 - INVITE (got response) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3' Request 102: Found Sep 6 22:04:30 DEBUG[5677] chan_sip.c: SIP response 100 to standard invite Sep 6 22:04:30 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Date: Wed, 06 Sep 2006 21:15:38 GMT CSeq: 102 INVITE Server: Cisco-CP7940G/7.5 Contact: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport (60) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as5b166e34 (67) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=000af434e1311e7017d73770-41d2b9bd (79) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:15:38 GMT (35) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 7: Server: Cisco-CP7940G/7.5 (25) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 8: Contact: (35) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 9: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE (65) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes (100) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:04:30 DEBUG[5677] chan_sip.c: Header 12: (0) Sep 6 22:04:30 VERBOSE[5677] logger.c: --- (12 headers 0 lines)Sep 6 22:04:30 VERBOSE[5677] logger.c: --- (12 headers 0 lines)--- Sep 6 22:04:30 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag Our tag: as5b166e34 Sep 6 22:04:30 DEBUG[5677] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3' Request 102: Found Sep 6 22:04:30 DEBUG[5677] chan_sip.c: SIP response 180 to standard invite Sep 6 22:04:30 DEBUG[5666] chan_sip.c: Checking device state for peer 1012 Sep 6 22:04:30 DEBUG[5666] devicestate.c: Changing state for SIP/1012 - state 6 (Ringing) Sep 6 22:04:30 VERBOSE[5715] logger.c: -- SIP/1012-08282898 is ringing Sep 6 22:04:30 DEBUG[5716] app_queue.c: Device 'SIP/1012' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Sep 6 22:04:31 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Date: Wed, 06 Sep 2006 21:15:39 GMT CSeq: 102 INVITE Server: Cisco-CP7940G/7.5 Contact: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes Supported: replaces Content-Length: 201 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 11624 0 IN IP4 10.1.20.52 s=SIP Call t=0 0 m=audio 30644 RTP/AVP 8 101 c=IN IP4 10.1.20.52 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK779aafa3;rport (60) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as5b166e34 (67) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=000af434e1311e7017d73770-41d2b9bd (79) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:15:39 GMT (35) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 7: Server: Cisco-CP7940G/7.5 (25) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 8: Contact: (35) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 9: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE (65) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes (100) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 11: Supported: replaces (19) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 12: Content-Length: 201 (19) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 13: Content-Type: application/sdp (29) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 14: Content-Disposition: session;handling=optional (46) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 15: (0) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: o=Cisco-SIPUA 11624 0 IN IP4 10.1.20.52 (39) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: m=audio 30644 RTP/AVP 8 101 (27) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-15 (15) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Line: a=sendrecv (10) Sep 6 22:04:31 VERBOSE[5677] logger.c: --- (15 headers 10 lines)Sep 6 22:04:31 VERBOSE[5677] logger.c: --- (15 headers 10 lines)--- Sep 6 22:04:31 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Acked pending invite 102 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Stopping retransmission on '265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3' of Request 102: Match Found Sep 6 22:04:31 DEBUG[5677] chan_sip.c: SIP response 200 to standard invite Sep 6 22:04:31 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:31 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:31 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.52:30644 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.52:30644 Sep 6 22:04:31 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:31 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:31 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:31 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: build_route: Contact hop: Sep 6 22:04:31 VERBOSE[5677] logger.c: list_route: hop: Sep 6 22:04:31 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:31 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.52, port 5060 Sep 6 22:04:31 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.52:5060: ACK sip:1012@10.1.20.52:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK36eb69b6;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Contact: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:31 DEBUG[5666] chan_sip.c: Checking device state for peer 1012 Sep 6 22:04:31 DEBUG[5666] devicestate.c: Changing state for SIP/1012 - state 2 (In use) Sep 6 22:04:31 VERBOSE[5715] logger.c: -- SIP/1012-08282898 answered Local/1012@local-cfd5,2 Sep 6 22:04:31 DEBUG[5717] app_queue.c: Device 'SIP/1012' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:31 VERBOSE[5713] logger.c: > Channel Agent/2000 was answered. Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'Set' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing Set("Agent/2000", "CALLFILE=agent-2000-o2c177331-20060906-220431") in new stack Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'SetAccount' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing SetAccount("Agent/2000", "test") in new stack Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'SetCDRUserField' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing SetCDRUserField("Agent/2000", "000/agent-2000-o2c177331-20060906-220431.gsm") in new stack Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'Monitor' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing Monitor("Agent/2000", "gsm|/fci/monitor/000/agent-2000-o2c177331-20060906-220431|m") in new stack Sep 6 22:04:31 DEBUG[5666] devicestate.c: Changing state for Local/1012@local - state 2 (In use) Sep 6 22:04:31 DEBUG[5666] devicestate.c: Changing state for Local/1012@local - state 2 (In use) Sep 6 22:04:31 DEBUG[5666] devicestate.c: Changing state for Agent/2000 - state 3 (Busy) Sep 6 22:04:31 DEBUG[5719] app_queue.c: Device 'Local/1012@local' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:31 DEBUG[5720] app_queue.c: Device 'Local/1012@local' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:31 DEBUG[5721] app_queue.c: Device 'Agent/2000' changed to state '3' (Busy) but we don't care because they're not a member of any queue. Sep 6 22:04:31 DEBUG[5713] pbx.c: Expression result is '0' Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'GotoIf' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing GotoIf("Agent/2000", "0?12:6") in new stack Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Goto (auto_dial,07966000000,6) Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'Set' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing Set("Agent/2000", "GROUP()=voip") in new stack Sep 6 22:04:31 DEBUG[5713] pbx.c: Function result is '1' Sep 6 22:04:31 DEBUG[5713] pbx.c: Expression result is '0' Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'GotoIf' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing GotoIf("Agent/2000", "0?12") in new stack Sep 6 22:04:31 DEBUG[5713] pbx.c: Not taking any branch Sep 6 22:04:31 DEBUG[5713] pbx.c: Launching 'Dial' Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Executing Dial("Agent/2000", "SIP/447966000000@mags") in new stack Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Setting NAT on RTP to 524288 Sep 6 22:04:31 DEBUG[5713] acl.c: ##### Testing 213.166.5.135 with 10.1.20.0 Sep 6 22:04:31 DEBUG[5713] acl.c: ##### Testing 213.166.5.135 with 172.28.1.0 Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Target address 213.166.5.135 is not local, substituting externip Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-8. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-7. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable GROUP. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-6. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-5. Sep 6 22:04:31 DEBUG[5713] channel.c: Copying hard-transferable variable MONITORED. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-4. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-3. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-2. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable CALLFILE. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable STACK-auto_dial-07966000000-1. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable project. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable person. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable orgref. Sep 6 22:04:31 DEBUG[5713] channel.c: Not copying variable conref. Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Outgoing Call for 447966000000 Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Updating call counter for outgoing call Sep 6 22:04:31 VERBOSE[5713] logger.c: We're at 89.105.104.74 port 16000 Sep 6 22:04:31 VERBOSE[5713] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 0: INVITE sip:447966000000@gk.magrathea.net SIP/2.0 (48) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK37aa1666;rport (64) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as31597662 (73) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 3: To: (39) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 4: Contact: (39) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 5: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net (58) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 9: Date: Wed, 06 Sep 2006 21:04:31 GMT (35) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 11: Content-Type: application/sdp (29) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 12: Content-Length: 160 (19) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Header 13: (0) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: v=0 (3) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: o=root 5662 5662 IN IP4 89.105.104.74 (37) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: s=session (9) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: c=IN IP4 89.105.104.74 (22) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: m=audio 16000 RTP/AVP 8 (23) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:31 DEBUG[5713] chan_sip.c: Line: a=silenceSupp:off - - - - (25) Sep 6 22:04:31 VERBOSE[5713] logger.c: 13 headers, 8 lines Sep 6 22:04:31 VERBOSE[5713] logger.c: Reliably Transmitting (NAT) to 213.166.5.135:5060: INVITE sip:447966000000@gk.magrathea.net SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK37aa1666;rport From: "->tests Oabcqfff" ;tag=as31597662 To: Contact: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:04:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 160 v=0 o=root 5662 5662 IN IP4 89.105.104.74 s=session c=IN IP4 89.105.104.74 t=0 0 m=audio 16000 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - --- Sep 6 22:04:31 DEBUG[5713] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #134 Sep 6 22:04:31 VERBOSE[5713] logger.c: -- Called 447966000000@mags Sep 6 22:04:31 DEBUG[5713] channel.c: Set channel SIP/mags-0829c328 to read format slin Sep 6 22:04:31 DEBUG[5713] channel.c: Set channel SIP/mags-0829c328 to write format slin Sep 6 22:04:31 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK37aa1666;rport=5060 From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.874b Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 102 INVITE Proxy-Authenticate: Digest realm="gk.magrathea.net", nonce="44ff391d2a72048a356ed2e33c1a30c353ab4692" Server: Sip EXpress router (0.8.99-dev (i386/linux)) Content-Length: 0 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 407 Proxy Authentication Required (41) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK37aa1666;rport=5060 (69) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as31597662 (73) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.874b (81) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net (58) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 5: CSeq: 102 INVITE (16) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 6: Proxy-Authenticate: Digest realm="gk.magrathea.net", nonce="44ff391d2a72048a356ed2e33c1a30c353ab4692" (101) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 7: Server: Sip EXpress router (0.8.99-dev (i386/linux)) (52) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 8: Content-Length: 0 (17) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 9: (0) Sep 6 22:04:31 VERBOSE[5677] logger.c: --- (9 headers 0 lines)Sep 6 22:04:31 VERBOSE[5677] logger.c: --- (9 headers 0 lines)--- Sep 6 22:04:31 DEBUG[5677] chan_sip.c: = Found Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag Our tag: as31597662 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Acked pending invite 102 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #134 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Stopping retransmission on '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' of Request 102: Match Found Sep 6 22:04:31 DEBUG[5677] chan_sip.c: SIP response 407 to standard invite Sep 6 22:04:31 VERBOSE[5677] logger.c: Transmitting (NAT) to 213.166.5.135:5060: ACK sip:447966000000@gk.magrathea.net SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK37aa1666;rport From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.874b Contact: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Auth attempt 1 on INVITE Sep 6 22:04:31 VERBOSE[5677] logger.c: We're at 89.105.104.74 port 16000 Sep 6 22:04:31 VERBOSE[5677] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:31 VERBOSE[5677] logger.c: Reliably Transmitting (NAT) to 213.166.5.135:5060: INVITE sip:447966000000@gk.magrathea.net SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport From: "->tests Oabcqfff" ;tag=as31597662 To: Contact: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Proxy-Authorization: Digest username="fullcircle", realm="gk.magrathea.net", algorithm=MD5, uri="sip:447966000000@gk.magrathea.net", nonce="44ff391d2a72048a356ed2e33c1a30c353ab4692", response="3a31ac7d322810dd7de7b306f5fc2ee1", opaque="" Date: Wed, 06 Sep 2006 21:04:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 160 v=0 o=root 5662 5663 IN IP4 89.105.104.74 s=session c=IN IP4 89.105.104.74 t=0 0 m=audio 16000 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - --- Sep 6 22:04:31 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #136 Sep 6 22:04:31 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport=5060 From: "->tests Oabcqfff" ;tag=as31597662 To: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 103 INVITE Server: Sip EXpress router (0.8.99-dev (i386/linux)) Content-Length: 0 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 100 trying -- your call is important to us (50) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport=5060 (69) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as31597662 (73) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 3: To: (39) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net (58) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 5: CSeq: 103 INVITE (16) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 6: Server: Sip EXpress router (0.8.99-dev (i386/linux)) (52) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 7: Content-Length: 0 (17) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: Header 8: (0) Sep 6 22:04:31 VERBOSE[5677] logger.c: --- (8 headers 0 lines)Sep 6 22:04:31 VERBOSE[5677] logger.c: --- (8 headers 0 lines)--- Sep 6 22:04:31 DEBUG[5677] chan_sip.c: = Found Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag Our tag: as31597662 Sep 6 22:04:31 DEBUG[5677] chan_sip.c: *** SIP TIMER: Cancelling retransmission #136 - INVITE (got response) Sep 6 22:04:31 DEBUG[5677] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' Request 103: Found Sep 6 22:04:31 DEBUG[5677] chan_sip.c: SIP response 100 to standard invite Sep 6 22:04:32 DEBUG[5715] channel.c: Planning to masquerade channel SIP/1012-08282898 into the structure of Local/1012@local-cfd5,1 Sep 6 22:04:32 DEBUG[5715] channel.c: Done planning to masquerade channel SIP/1012-08282898 into the structure of Local/1012@local-cfd5,1 Sep 6 22:04:32 DEBUG[5715] chan_local.c: Not posting to queue since already masked on 'Local/1012@local-cfd5,2' Sep 6 22:04:32 DEBUG[5713] channel.c: Actually Masquerading SIP/1012-08282898(6) into the structure of Local/1012@local-cfd5,1(6) Sep 6 22:04:32 DEBUG[5713] channel.c: Got clone lock for masquerade on 'SIP/1012-08282898' at 0x8288334 Sep 6 22:04:32 DEBUG[5713] channel.c: Putting channel SIP/1012-08282898 in 64/64 formats Sep 6 22:04:32 DEBUG[5713] channel.c: Released clone lock on 'Local/1012@local-cfd5,1' Sep 6 22:04:32 DEBUG[5715] channel.c: Didn't get a frame from channel: Local/1012@local-cfd5,2 Sep 6 22:04:32 DEBUG[5713] channel.c: Done Masquerading SIP/1012-08282898 (6) Sep 6 22:04:32 DEBUG[5715] channel.c: Bridge stops bridging channels Local/1012@local-cfd5,2 and Local/1012@local-cfd5,1 Sep 6 22:04:32 DEBUG[5713] chan_agent.c: Bridge on 'SIP/1012-08282898' being set to 'Agent/2000' (3) Sep 6 22:04:32 DEBUG[5715] channel.c: Hanging up zombie 'Local/1012@local-cfd5,1' Sep 6 22:04:32 DEBUG[5713] chan_agent.c: Native formats changing from 64 to 8 Sep 6 22:04:32 DEBUG[5713] chan_agent.c: Resetting read to 64 and write to 64 Sep 6 22:04:32 DEBUG[5666] devicestate.c: Changing state for Local/1012@local - state 2 (In use) Sep 6 22:04:32 DEBUG[5715] app_dial.c: Exiting with DIALSTATUS=ANSWER. Sep 6 22:04:32 DEBUG[5713] channel.c: Set channel Agent/2000 to read format slin Sep 6 22:04:32 DEBUG[5722] app_queue.c: Device 'Local/1012@local' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:32 DEBUG[5715] pbx.c: Spawn extension (local,1012,4) exited non-zero on 'Local/1012@local-cfd5,2' Sep 6 22:04:32 DEBUG[5713] channel.c: Set channel Agent/2000 to write format slin Sep 6 22:04:32 DEBUG[5713] channel.c: Set channel SIP/1012-08282898 to read format alaw Sep 6 22:04:32 DEBUG[5713] channel.c: Set channel SIP/1012-08282898 to write format alaw Sep 6 22:04:32 DEBUG[5715] channel.c: Hanging up channel 'Local/1012@local-cfd5,2' Sep 6 22:04:32 DEBUG[5666] devicestate.c: Changing state for Local/1012@local - state 0 (Unknown) Sep 6 22:04:32 DEBUG[5723] app_queue.c: Device 'Local/1012@local' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Sep 6 22:04:36 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport=5060 From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=DCE5A610-130B Date: Wed, 06 Sep 2006 21:04:31 gmt Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Server: Cisco-SIPGateway/IOS-12.x CSeq: 103 INVITE Allow-Events: telephone-event Contact: Record-Route: Content-Disposition: session;handling=required Content-Type: application/sdp Content-Length: 182 v=0 o=CiscoSystemsSIP-GW-UserAgent 9714 5435 IN IP4 213.166.5.133 s=SIP Call c=IN IP4 213.166.5.133 t=0 0 m=audio 16438 RTP/AVP 8 c=IN IP4 213.166.5.133 a=rtpmap:8 PCMA/8000 Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 183 Session Progress (28) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport=5060 (69) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as31597662 (73) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=DCE5A610-130B (57) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 4: Date: Wed, 06 Sep 2006 21:04:31 gmt (35) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net (58) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 7: CSeq: 103 INVITE (16) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 8: Allow-Events: telephone-event (29) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 9: Contact: (48) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 10: Record-Route: (55) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 11: Content-Disposition: session;handling=required (46) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 12: Content-Type: application/sdp (29) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 13: Content-Length: 182 (19) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Header 14: (0) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: o=CiscoSystemsSIP-GW-UserAgent 9714 5435 IN IP4 213.166.5.133 (61) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: c=IN IP4 213.166.5.133 (22) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: m=audio 16438 RTP/AVP 8 (23) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: c=IN IP4 213.166.5.133 (22) Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:36 VERBOSE[5677] logger.c: --- (14 headers 8 lines)Sep 6 22:04:36 VERBOSE[5677] logger.c: --- (14 headers 8 lines)--- Sep 6 22:04:36 DEBUG[5677] chan_sip.c: = Found Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag Our tag: as31597662 Sep 6 22:04:36 DEBUG[5677] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' Request 103: Found Sep 6 22:04:36 DEBUG[5677] chan_sip.c: SIP response 183 to standard invite Sep 6 22:04:36 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:36 VERBOSE[5677] logger.c: Peer audio RTP is at port 213.166.5.133:16438 Sep 6 22:04:36 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 213.166.5.133:16438 Sep 6 22:04:36 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:36 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:36 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Sep 6 22:04:36 VERBOSE[5713] logger.c: -- SIP/mags-0829c328 is making progress passing it to Agent/2000 Sep 6 22:04:36 DEBUG[5713] rtp.c: Ooh, format changed from unknown to alaw Sep 6 22:04:37 DEBUG[5713] rtp.c: Ooh, format changed from unknown to alaw Sep 6 22:04:39 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport=5060 From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=DCE5A610-130B Date: Wed, 06 Sep 2006 21:04:31 gmt Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Server: Cisco-SIPGateway/IOS-12.x CSeq: 103 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO Allow-Events: telephone-event Contact: Record-Route: Content-Type: application/sdp Content-Length: 182 v=0 o=CiscoSystemsSIP-GW-UserAgent 9714 5435 IN IP4 213.166.5.133 s=SIP Call c=IN IP4 213.166.5.133 t=0 0 m=audio 16438 RTP/AVP 8 c=IN IP4 213.166.5.133 a=rtpmap:8 PCMA/8000 Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK173f9018;rport=5060 (69) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as31597662 (73) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=DCE5A610-130B (57) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 4: Date: Wed, 06 Sep 2006 21:04:31 gmt (35) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net (58) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 7: CSeq: 103 INVITE (16) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO (86) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 9: Allow-Events: telephone-event (29) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 10: Contact: (48) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 11: Record-Route: (55) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 12: Content-Type: application/sdp (29) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 13: Content-Length: 182 (19) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Header 14: (0) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: o=CiscoSystemsSIP-GW-UserAgent 9714 5435 IN IP4 213.166.5.133 (61) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: c=IN IP4 213.166.5.133 (22) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: m=audio 16438 RTP/AVP 8 (23) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: c=IN IP4 213.166.5.133 (22) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:39 VERBOSE[5677] logger.c: --- (14 headers 8 lines)Sep 6 22:04:39 VERBOSE[5677] logger.c: --- (14 headers 8 lines)--- Sep 6 22:04:39 DEBUG[5677] chan_sip.c: = Found Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag DCE5A610-130B Our tag: as31597662 Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Acked pending invite 103 Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Stopping retransmission on '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' of Request 103: Match Found Sep 6 22:04:39 DEBUG[5677] chan_sip.c: SIP response 200 to standard invite Sep 6 22:04:39 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:39 VERBOSE[5677] logger.c: Peer audio RTP is at port 213.166.5.133:16438 Sep 6 22:04:39 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 213.166.5.133:16438 Sep 6 22:04:39 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:39 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:39 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Sep 6 22:04:39 DEBUG[5677] chan_sip.c: build_route: Record-Route hop: Sep 6 22:04:39 VERBOSE[5677] logger.c: list_route: hop: Sep 6 22:04:39 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:39 VERBOSE[5677] logger.c: set_destination: set destination to 213.166.5.135, port 5060 Sep 6 22:04:39 VERBOSE[5677] logger.c: Transmitting (NAT) to 213.166.5.135:5060: ACK sip:00447966000000@213.166.5.133:5060 SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK10415d3e;rport Route: From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=DCE5A610-130B Contact: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:39 VERBOSE[5713] logger.c: -- SIP/mags-0829c328 answered Agent/2000 Sep 6 22:04:39 DEBUG[5713] channel.c: Set channel Agent/2000 to read format alaw Sep 6 22:04:39 DEBUG[5713] channel.c: Set channel SIP/mags-0829c328 to write format alaw Sep 6 22:04:39 DEBUG[5713] channel.c: Set channel SIP/mags-0829c328 to read format alaw Sep 6 22:04:39 DEBUG[5713] channel.c: Set channel Agent/2000 to write format alaw Sep 6 22:04:39 DEBUG[5666] chan_sip.c: Checking device state for peer mags Sep 6 22:04:39 DEBUG[5666] devicestate.c: Changing state for SIP/mags - state 2 (In use) Sep 6 22:04:39 DEBUG[5724] app_queue.c: Device 'SIP/mags' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:42 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: INVITE sip:07966000000@10.1.20.3:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK3850f8de From: ;tag=000af434e1311e7017d73770-41d2b9bd To: "->tests Oabcqfff" ;tag=as5b166e34 Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:15:50 GMT CSeq: 101 INVITE User-Agent: Cisco-CP7940G/7.5 Contact: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 251 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 11624 1 IN IP4 10.1.20.52 s=SIP Call t=0 0 m=audio 30644 RTP/AVP 8 0 18 101 c=IN IP4 10.1.20.52 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendonly Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 0: INVITE sip:07966000000@10.1.20.3:5060 SIP/2.0 (45) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK3850f8de (55) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 2: From: ;tag=000af434e1311e7017d73770-41d2b9bd (81) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 3: To: "->tests Oabcqfff" ;tag=as5b166e34 (65) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:15:50 GMT (35) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 7: CSeq: 101 INVITE (16) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 9: Contact: (35) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes (100) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 251 (19) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 12: Content-Type: application/sdp (29) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 13: Content-Disposition: session;handling=optional (46) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 14: (0) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: o=Cisco-SIPUA 11624 1 IN IP4 10.1.20.52 (39) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: m=audio 30644 RTP/AVP 8 0 18 101 (32) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-15 (15) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Line: a=sendonly (10) Sep 6 22:04:42 VERBOSE[5677] logger.c: --- (14 headers 12 lines)Sep 6 22:04:42 VERBOSE[5677] logger.c: --- (14 headers 12 lines)--- Sep 6 22:04:42 DEBUG[5677] chan_sip.c: = No match Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag DCE5A610-130B Our tag: as31597662 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Sep 6 22:04:42 VERBOSE[5677] logger.c: Using INVITE request as basis request - 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Sep 6 22:04:42 VERBOSE[5677] logger.c: Sending to 10.1.20.52 : 5060 (non-NAT) Sep 6 22:04:42 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:42 VERBOSE[5677] logger.c: Found RTP audio format 0 Sep 6 22:04:42 VERBOSE[5677] logger.c: Found RTP audio format 18 Sep 6 22:04:42 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:42 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.52:30644 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.52:30644 Sep 6 22:04:42 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:42 VERBOSE[5677] logger.c: Found description format PCMU Sep 6 22:04:42 VERBOSE[5677] logger.c: Found description format G729 Sep 6 22:04:42 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:42 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:42 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:42 DEBUG[5677] chan_agent.c: Asked for bridged channel on 'SIP/1012-08282898'/'Agent/2000', returning 'SIP/mags-0829c328' Sep 6 22:04:42 DEBUG[5677] channel.c: Set channel SIP/mags-0829c328 to write format slin Sep 6 22:04:42 VERBOSE[5677] logger.c: -- Started music on hold, class 'default', on channel 'SIP/mags-0829c328' Sep 6 22:04:42 DEBUG[5677] channel.c: Scheduling timer at 160 sample intervals Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Got a SIP re-invite for call 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Sep 6 22:04:42 VERBOSE[5677] logger.c: We're at 10.1.20.3 port 16064 Sep 6 22:04:42 VERBOSE[5677] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:42 VERBOSE[5677] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:42 VERBOSE[5677] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK3850f8de;received=10.1.20.52 From: ;tag=000af434e1311e7017d73770-41d2b9bd To: "->tests Oabcqfff" ;tag=as5b166e34 Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 208 v=0 o=root 5662 5663 IN IP4 10.1.20.3 s=session c=IN IP4 10.1.20.3 t=0 0 m=audio 16064 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:42 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #137 Sep 6 22:04:42 DEBUG[5713] channel.c: Generator got voice, switching to phase locked mode Sep 6 22:04:42 DEBUG[5713] channel.c: Scheduling timer at 0 sample intervals Sep 6 22:04:42 DEBUG[5713] rtp.c: Difference is 776, ms is 117 Sep 6 22:04:42 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: ACK sip:07966000000@10.1.20.3:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK7c07d5da From: ;tag=000af434e1311e7017d73770-41d2b9bd To: "->tests Oabcqfff" ;tag=as5b166e34 Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:15:50 GMT CSeq: 101 ACK User-Agent: Cisco-CP7940G/7.5 Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 0: ACK sip:07966000000@10.1.20.3:5060 SIP/2.0 (42) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK7c07d5da (55) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 2: From: ;tag=000af434e1311e7017d73770-41d2b9bd (81) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 3: To: "->tests Oabcqfff" ;tag=as5b166e34 (65) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:15:50 GMT (35) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 7: CSeq: 101 ACK (13) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 9: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes (100) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 10: Content-Length: 0 (17) Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Header 11: (0) Sep 6 22:04:42 VERBOSE[5677] logger.c: --- (11 headers 0 lines)Sep 6 22:04:42 VERBOSE[5677] logger.c: --- (11 headers 0 lines)--- Sep 6 22:04:42 DEBUG[5677] chan_sip.c: = No match Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag DCE5A610-130B Our tag: as31597662 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Sep 6 22:04:42 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #137 Sep 6 22:04:42 DEBUG[5677] chan_sip.c: Stopping retransmission on '265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3' of Response 101: Match Found Sep 6 22:04:44 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: INVITE sip:1015@10.1.20.3 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK6f5f87e1 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:15:52 GMT CSeq: 101 INVITE User-Agent: Cisco-CP7940G/7.5 Contact: Expires: 180 Accept: application/sdp Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes Supported: replaces Content-Length: 251 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 27985 0 IN IP4 10.1.20.52 s=SIP Call t=0 0 m=audio 30648 RTP/AVP 8 0 18 101 c=IN IP4 10.1.20.52 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 0: INVITE sip:1015@10.1.20.3 SIP/2.0 (33) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK6f5f87e1 (55) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 2: From: "1012" ;tag=000af434e1311e717cfc5200-1296096d (71) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 3: To: (24) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:15:52 GMT (35) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 7: CSeq: 101 INVITE (16) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 9: Contact: (35) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 10: Expires: 180 (12) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 11: Accept: application/sdp (23) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 12: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE (65) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 13: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes (101) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 14: Supported: replaces (19) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 15: Content-Length: 251 (19) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 16: Content-Type: application/sdp (29) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 17: Content-Disposition: session;handling=optional (46) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Header 18: (0) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: o=Cisco-SIPUA 27985 0 IN IP4 10.1.20.52 (39) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: m=audio 30648 RTP/AVP 8 0 18 101 (32) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-15 (15) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Line: a=sendrecv (10) Sep 6 22:04:44 VERBOSE[5677] logger.c: --- (18 headers 12 lines)Sep 6 22:04:44 VERBOSE[5677] logger.c: --- (18 headers 12 lines)--- Sep 6 22:04:44 DEBUG[5677] chan_sip.c: = No match Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag DCE5A610-130B Our tag: as31597662 Sep 6 22:04:44 DEBUG[5677] chan_sip.c: = No match Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:44 DEBUG[5677] acl.c: ##### Testing 10.1.20.52 with 10.1.20.0 Sep 6 22:04:44 DEBUG[5677] acl.c: ##### Testing 10.1.20.52 with 172.28.1.0 Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Allocating new SIP dialog for 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 - INVITE (With RTP) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Begin: parsing SIP "Supported: replaces" Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Found SIP option: -replaces- Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Matched SIP option: replaces Sep 6 22:04:44 DEBUG[5677] chan_sip.c: * SIP extension value: 1 for call 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Sep 6 22:04:44 VERBOSE[5677] logger.c: Using INVITE request as basis request - 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Sep 6 22:04:44 VERBOSE[5677] logger.c: Sending to 10.1.20.52 : 5060 (non-NAT) Sep 6 22:04:44 DEBUG[5677] chan_sip.c: Setting NAT on RTP to 0 Sep 6 22:04:44 VERBOSE[5677] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK6f5f87e1;received=10.1.20.52 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as31996767 Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="phoneserver", nonce="4ab214da" Content-Length: 0 --- Sep 6 22:04:44 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #138 Sep 6 22:04:44 VERBOSE[5677] logger.c: Scheduling destruction of call '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' in 15000 ms Sep 6 22:04:44 VERBOSE[5677] logger.c: Found user '1012' Sep 6 22:04:45 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:52241: ACK sip:1015@10.1.20.3 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK6f5f87e1 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as31996767 Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Date: Wed, 06 Sep 2006 21:15:53 GMT CSeq: 101 ACK Content-Length: 0 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 0: ACK sip:1015@10.1.20.3 SIP/2.0 (30) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK6f5f87e1 (55) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 2: From: "1012" ;tag=000af434e1311e717cfc5200-1296096d (71) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=as31996767 (39) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:15:53 GMT (35) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 6: CSeq: 101 ACK (13) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 7: Content-Length: 0 (17) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 8: (0) Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (8 headers 0 lines)Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (8 headers 0 lines)--- Sep 6 22:04:45 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as31996767 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Sep 6 22:04:45 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #138 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Stopping retransmission on '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' of Response 101: Match Found Sep 6 22:04:45 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: INVITE sip:1015@10.1.20.3 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1fc793ef From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:15:53 GMT CSeq: 102 INVITE User-Agent: Cisco-CP7940G/7.5 Contact: Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3",response="8e8ee972430eb11ef6f9fb29998482dc",nonce="4ab214da",algorithm=MD5 Expires: 180 Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes Content-Length: 251 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 27985 0 IN IP4 10.1.20.52 s=SIP Call t=0 0 m=audio 30648 RTP/AVP 8 0 18 101 c=IN IP4 10.1.20.52 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 0: INVITE sip:1015@10.1.20.3 SIP/2.0 (33) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1fc793ef (55) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 2: From: "1012" ;tag=000af434e1311e717cfc5200-1296096d (71) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 3: To: (24) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:15:53 GMT (35) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 7: CSeq: 102 INVITE (16) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 9: Contact: (35) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 10: Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3",response="8e8ee972430eb11ef6f9fb29998482dc",nonce="4ab214da",algorithm=MD5 (163) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 11: Expires: 180 (12) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 12: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes (101) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 13: Content-Length: 251 (19) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 14: Content-Type: application/sdp (29) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 15: Content-Disposition: session;handling=optional (46) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 16: (0) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: o=Cisco-SIPUA 27985 0 IN IP4 10.1.20.52 (39) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: m=audio 30648 RTP/AVP 8 0 18 101 (32) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-15 (15) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Line: a=sendrecv (10) Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (16 headers 12 lines)Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (16 headers 12 lines)--- Sep 6 22:04:45 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as31996767 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Sep 6 22:04:45 VERBOSE[5677] logger.c: Using INVITE request as basis request - 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Sep 6 22:04:45 VERBOSE[5677] logger.c: Sending to 10.1.20.52 : 5060 (non-NAT) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Setting NAT on RTP to 0 Sep 6 22:04:45 VERBOSE[5677] logger.c: Found user '1012' Sep 6 22:04:45 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:45 VERBOSE[5677] logger.c: Found RTP audio format 0 Sep 6 22:04:45 VERBOSE[5677] logger.c: Found RTP audio format 18 Sep 6 22:04:45 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:45 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.52:30648 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.52:30648 Sep 6 22:04:45 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:45 VERBOSE[5677] logger.c: Found description format PCMU Sep 6 22:04:45 VERBOSE[5677] logger.c: Found description format G729 Sep 6 22:04:45 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:45 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:45 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Checking SIP call limits for device 1012 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Updating call counter for incoming call Sep 6 22:04:45 VERBOSE[5677] logger.c: Looking for 1015 in demo (domain 10.1.20.3) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: build_route: Contact hop: Sep 6 22:04:45 VERBOSE[5677] logger.c: list_route: hop: Sep 6 22:04:45 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1fc793ef;received=10.1.20.52 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Sep 6 22:04:45 DEBUG[5666] chan_sip.c: Checking device state for peer 1012 Sep 6 22:04:45 DEBUG[5666] devicestate.c: Changing state for SIP/1012 - state 2 (In use) Sep 6 22:04:45 DEBUG[5725] pbx.c: Expression result is '1' Sep 6 22:04:45 DEBUG[5725] pbx.c: Launching 'GotoIf' Sep 6 22:04:45 DEBUG[5726] app_queue.c: Device 'SIP/1012' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:45 VERBOSE[5725] logger.c: -- Executing GotoIf("SIP/1012-08294f30", "1?2:3") in new stack Sep 6 22:04:45 VERBOSE[5725] logger.c: -- Goto (demo,1015,2) Sep 6 22:04:45 DEBUG[5725] pbx.c: Function result is 'Walter McDonald' Sep 6 22:04:45 DEBUG[5725] pbx.c: Launching 'SetCallerID' Sep 6 22:04:45 VERBOSE[5725] logger.c: -- Executing SetCallerID("SIP/1012-08294f30", "Walter McDonald <2000>") in new stack Sep 6 22:04:45 DEBUG[5725] pbx.c: Launching 'Dial' Sep 6 22:04:45 VERBOSE[5725] logger.c: -- Executing Dial("SIP/1012-08294f30", "SIP/1015|500") in new stack Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Setting NAT on RTP to 0 Sep 6 22:04:45 DEBUG[5725] acl.c: ##### Testing 10.1.20.55 with 10.1.20.0 Sep 6 22:04:45 DEBUG[5725] acl.c: ##### Testing 10.1.20.55 with 172.28.1.0 Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable STACK-demo-1015-3. Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable STACK-demo-1015-2. Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable STACK-demo-1015-1. Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable SIPCALLID. Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable SIPUSERAGENT. Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable SIPDOMAIN. Sep 6 22:04:45 DEBUG[5725] channel.c: Not copying variable SIPURI. Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Outgoing Call for 1015 Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Updating call counter for outgoing call Sep 6 22:04:45 VERBOSE[5725] logger.c: We're at 10.1.20.3 port 16036 Sep 6 22:04:45 VERBOSE[5725] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:45 VERBOSE[5725] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 0: INVITE sip:1015@10.1.20.55:5060 SIP/2.0 (39) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport (60) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 3: To: (30) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 4: Contact: (29) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 9: Date: Wed, 06 Sep 2006 21:04:45 GMT (35) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 11: Content-Type: application/sdp (29) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 12: Content-Length: 208 (19) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Header 13: (0) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: v=0 (3) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: o=root 5662 5662 IN IP4 10.1.20.3 (33) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: s=session (9) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: c=IN IP4 10.1.20.3 (18) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: m=audio 16036 RTP/AVP 8 101 (27) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: a=fmtp:101 0-16 (15) Sep 6 22:04:45 DEBUG[5725] chan_sip.c: Line: a=silenceSupp:off - - - - (25) Sep 6 22:04:45 VERBOSE[5725] logger.c: 13 headers, 10 lines Sep 6 22:04:45 VERBOSE[5725] logger.c: Reliably Transmitting (no NAT) to 10.1.20.55:5060: INVITE sip:1015@10.1.20.55:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport From: "Walter McDonald" ;tag=as69758514 To: Contact: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:04:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 208 v=0 o=root 5662 5662 IN IP4 10.1.20.3 s=session c=IN IP4 10.1.20.3 t=0 0 m=audio 16036 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:45 DEBUG[5725] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #140 Sep 6 22:04:45 VERBOSE[5725] logger.c: -- Called 1015 Sep 6 22:04:45 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.55:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 CSeq: 102 INVITE Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Contact: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 Content-Length: 0 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport (60) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 4: CSeq: 102 INVITE (16) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 6: Contact: (35) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 (54) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 8: Content-Length: 0 (17) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 9: (0) Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (9 headers 0 lines)Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (9 headers 0 lines)--- Sep 6 22:04:45 DEBUG[5677] chan_sip.c: = Found Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag Our tag: as69758514 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: *** SIP TIMER: Cancelling retransmission #140 - INVITE (got response) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' Request 102: Found Sep 6 22:04:45 DEBUG[5677] chan_sip.c: SIP response 100 to standard invite Sep 6 22:04:45 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.55:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 CSeq: 102 INVITE Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Contact: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 Allow-Events: talk,hold,conference Content-Length: 0 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport (60) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 4: CSeq: 102 INVITE (16) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 6: Contact: (35) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 (54) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 8: Allow-Events: talk,hold,conference (34) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 9: Content-Length: 0 (17) Sep 6 22:04:45 DEBUG[5677] chan_sip.c: Header 10: (0) Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (10 headers 0 lines)Sep 6 22:04:45 VERBOSE[5677] logger.c: --- (10 headers 0 lines)--- Sep 6 22:04:45 DEBUG[5677] chan_sip.c: = Found Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:45 DEBUG[5677] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' Request 102: Found Sep 6 22:04:45 DEBUG[5677] chan_sip.c: SIP response 180 to standard invite Sep 6 22:04:45 VERBOSE[5725] logger.c: -- SIP/1015-082a41c0 is ringing Sep 6 22:04:45 DEBUG[5666] chan_sip.c: Checking device state for peer 1015 Sep 6 22:04:45 VERBOSE[5725] logger.c: Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1fc793ef;received=10.1.20.52 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as3c4c872c Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Sep 6 22:04:45 DEBUG[5666] devicestate.c: Changing state for SIP/1015 - state 6 (Ringing) Sep 6 22:04:45 DEBUG[5727] app_queue.c: Device 'SIP/1015' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Sep 6 22:04:50 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.55:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 CSeq: 102 INVITE Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 Content-Type: application/sdp Content-Length: 183 v=0 o=- 1157576678 1157576678 IN IP4 10.1.20.55 s=Polycom IP Phone c=IN IP4 10.1.20.55 t=0 0 m=audio 2226 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK37edbc08;rport (60) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 4: CSeq: 102 INVITE (16) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 6: Contact: (35) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 (54) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 9: Content-Type: application/sdp (29) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 10: Content-Length: 183 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 11: (0) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: o=- 1157576678 1157576678 IN IP4 10.1.20.55 (43) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: s=Polycom IP Phone (18) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.55 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: m=audio 2226 RTP/AVP 8 101 (26) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (11 headers 8 lines)Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (11 headers 8 lines)--- Sep 6 22:04:50 DEBUG[5677] chan_sip.c: = Found Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Acked pending invite 102 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Stopping retransmission on '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' of Request 102: Match Found Sep 6 22:04:50 DEBUG[5677] chan_sip.c: SIP response 200 to standard invite Sep 6 22:04:50 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:50 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.55:2226 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.55:2226 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:50 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:50 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:50 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: build_route: Contact hop: Sep 6 22:04:50 VERBOSE[5677] logger.c: list_route: hop: Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.55, port 5060 Sep 6 22:04:50 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.55:5060: ACK sip:1015@10.1.20.55:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK346da8bb;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 Contact: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:50 DEBUG[5666] chan_sip.c: Checking device state for peer 1015 Sep 6 22:04:50 DEBUG[5666] devicestate.c: Changing state for SIP/1015 - state 2 (In use) Sep 6 22:04:50 DEBUG[5728] app_queue.c: Device 'SIP/1015' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:50 VERBOSE[5725] logger.c: -- SIP/1015-082a41c0 answered SIP/1012-08294f30 Sep 6 22:04:50 DEBUG[5725] chan_sip.c: sip_answer(SIP/1012-08294f30) Sep 6 22:04:50 DEBUG[5666] chan_sip.c: Checking device state for peer 1012 Sep 6 22:04:50 DEBUG[5666] channel.c: Avoiding initial deadlock for 'SIP/1012-08294f30' Sep 6 22:04:50 VERBOSE[5725] logger.c: We're at 10.1.20.3 port 16050 Sep 6 22:04:50 VERBOSE[5725] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:50 VERBOSE[5725] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:50 VERBOSE[5725] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1fc793ef;received=10.1.20.52 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as3c4c872c Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 208 v=0 o=root 5662 5662 IN IP4 10.1.20.3 s=session c=IN IP4 10.1.20.3 t=0 0 m=audio 16050 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:50 DEBUG[5725] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #141 Sep 6 22:04:50 VERBOSE[5725] logger.c: -- Attempting native bridge of SIP/1012-08294f30 and SIP/1015-082a41c0 Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Deferring reinvite on SIP '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' - It's audio will be redirected to IP 10.1.20.55 Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Sending reinvite on SIP '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' - It's audio soon redirected to IP 10.1.20.52 Sep 6 22:04:50 VERBOSE[5725] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:50 VERBOSE[5725] logger.c: set_destination: set destination to 10.1.20.55, port 5060 Sep 6 22:04:50 VERBOSE[5725] logger.c: We're at 10.1.20.3 port 16036 Sep 6 22:04:50 VERBOSE[5725] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:50 VERBOSE[5725] logger.c: Adding codec 0x4 (ulaw) to SDP Sep 6 22:04:50 VERBOSE[5725] logger.c: Adding codec 0x100 (g729) to SDP Sep 6 22:04:50 VERBOSE[5725] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 0: INVITE sip:1015@10.1.20.55:5060 SIP/2.0 (39) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK2545971a;rport (60) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 4: Contact: (29) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 6: CSeq: 103 INVITE (16) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (43) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 11: Content-Type: application/sdp (29) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 12: Content-Length: 281 (19) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Header 13: (0) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: v=0 (3) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: o=root 5662 5663 IN IP4 10.1.20.52 (34) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: s=session (9) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: m=audio 30648 RTP/AVP 8 0 18 101 (32) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=fmtp:18 annexb=no (19) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=fmtp:101 0-16 (15) Sep 6 22:04:50 DEBUG[5725] chan_sip.c: Line: a=silenceSupp:off - - - - (25) Sep 6 22:04:50 DEBUG[5666] channel.c: Avoiding initial deadlock for 'SIP/1012-08294f30' Sep 6 22:04:50 VERBOSE[5725] logger.c: 13 headers, 13 lines Sep 6 22:04:50 VERBOSE[5725] logger.c: Reliably Transmitting (no NAT) to 10.1.20.55:5060: INVITE sip:1015@10.1.20.55:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK2545971a;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 Contact: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 281 v=0 o=root 5662 5663 IN IP4 10.1.20.52 s=session c=IN IP4 10.1.20.52 t=0 0 m=audio 30648 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:50 DEBUG[5725] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #142 Sep 6 22:04:50 DEBUG[5666] devicestate.c: Changing state for SIP/1012 - state 2 (In use) Sep 6 22:04:50 DEBUG[5729] app_queue.c: Device 'SIP/1012' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:50 DEBUG[5725] rtp.c: Ooh, format changed from unknown to alaw Sep 6 22:04:50 DEBUG[5725] rtp.c: Ooh, format changed from unknown to alaw Sep 6 22:04:50 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.55:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK2545971a;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 CSeq: 103 INVITE Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 Content-Type: application/sdp Content-Length: 183 v=0 o=- 1157576678 1157576679 IN IP4 10.1.20.55 s=Polycom IP Phone c=IN IP4 10.1.20.55 t=0 0 m=audio 2226 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK2545971a;rport (60) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 4: CSeq: 103 INVITE (16) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 6: Contact: (35) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 (54) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 9: Content-Type: application/sdp (29) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 10: Content-Length: 183 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 11: (0) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: o=- 1157576678 1157576679 IN IP4 10.1.20.55 (43) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: s=Polycom IP Phone (18) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.55 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: m=audio 2226 RTP/AVP 8 101 (26) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (11 headers 8 lines)Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (11 headers 8 lines)--- Sep 6 22:04:50 DEBUG[5677] chan_sip.c: = Found Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Acked pending invite 103 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #142 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Stopping retransmission on '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' of Request 103: Match Found Sep 6 22:04:50 DEBUG[5677] chan_sip.c: SIP response 200 to RE-invite on outgoing call 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:50 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.55:2226 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.55:2226 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:50 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:50 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:50 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: build_route: Retaining previous route: Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.55, port 5060 Sep 6 22:04:50 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.55:5060: ACK sip:1015@10.1.20.55:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK24fc6e40;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 Contact: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:50 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: ACK sip:1015@10.1.20.3:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK4ddd664e From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as3c4c872c Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:15:58 GMT CSeq: 102 ACK User-Agent: Cisco-CP7940G/7.5 Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3",response="8e8ee972430eb11ef6f9fb29998482dc",nonce="4ab214da",algorithm=MD5 Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 0: ACK sip:1015@10.1.20.3:5060 SIP/2.0 (35) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK4ddd664e (55) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 2: From: "1012" ;tag=000af434e1311e717cfc5200-1296096d (71) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=as3c4c872c (39) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:15:58 GMT (35) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 7: CSeq: 102 ACK (13) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 9: Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3",response="8e8ee972430eb11ef6f9fb29998482dc",nonce="4ab214da",algorithm=MD5 (163) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes (101) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 12: (0) Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (12 headers 0 lines)Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (12 headers 0 lines)--- Sep 6 22:04:50 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:50 DEBUG[5677] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Sep 6 22:04:50 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #141 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Stopping retransmission on '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' of Response 102: Match Found Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Sending pending reinvite on '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.52, port 5060 Sep 6 22:04:50 VERBOSE[5677] logger.c: We're at 10.1.20.3 port 16050 Sep 6 22:04:50 VERBOSE[5677] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:50 VERBOSE[5677] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 0: INVITE sip:1012@10.1.20.52:5060 SIP/2.0 (39) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK7a5b5282;rport (60) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 2: From: ;tag=as3c4c872c (41) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 3: To: "1012" ;tag=000af434e1311e717cfc5200-1296096d (69) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 4: Contact: (29) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (43) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 11: Content-Type: application/sdp (29) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 12: Content-Length: 209 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 13: (0) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: o=root 5662 5663 IN IP4 10.1.20.55 (34) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: s=session (9) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.55 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: m=audio 2226 RTP/AVP 8 101 (26) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-16 (15) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=silenceSupp:off - - - - (25) Sep 6 22:04:50 VERBOSE[5677] logger.c: 13 headers, 10 lines Sep 6 22:04:50 VERBOSE[5677] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: INVITE sip:1012@10.1.20.52:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK7a5b5282;rport From: ;tag=as3c4c872c To: "1012" ;tag=000af434e1311e717cfc5200-1296096d Contact: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 209 v=0 o=root 5662 5663 IN IP4 10.1.20.55 s=session c=IN IP4 10.1.20.55 t=0 0 m=audio 2226 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:50 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #143 Sep 6 22:04:50 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK7a5b5282;rport From: ;tag=as3c4c872c To: "1012" ;tag=000af434e1311e717cfc5200-1296096d Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Date: Wed, 06 Sep 2006 21:15:58 GMT CSeq: 102 INVITE Server: Cisco-CP7940G/7.5 Contact: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes Supported: replaces Content-Length: 201 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 27985 1 IN IP4 10.1.20.52 s=SIP Call t=0 0 m=audio 30648 RTP/AVP 8 101 c=IN IP4 10.1.20.52 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK7a5b5282;rport (60) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 2: From: ;tag=as3c4c872c (41) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 3: To: "1012" ;tag=000af434e1311e717cfc5200-1296096d (69) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:15:58 GMT (35) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 7: Server: Cisco-CP7940G/7.5 (25) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 8: Contact: (35) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 9: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE (65) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes (101) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 11: Supported: replaces (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 12: Content-Length: 201 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 13: Content-Type: application/sdp (29) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 14: Content-Disposition: session;handling=optional (46) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Header 15: (0) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: o=Cisco-SIPUA 27985 1 IN IP4 10.1.20.52 (39) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: m=audio 30648 RTP/AVP 8 101 (27) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-15 (15) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Line: a=sendrecv (10) Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (15 headers 10 lines)Sep 6 22:04:50 VERBOSE[5677] logger.c: --- (15 headers 10 lines)--- Sep 6 22:04:50 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Acked pending invite 102 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #143 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Stopping retransmission on '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' of Request 102: Match Found Sep 6 22:04:50 DEBUG[5677] chan_sip.c: SIP response 200 to RE-invite on outgoing call 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:50 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.52:30648 Sep 6 22:04:50 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.52:30648 Sep 6 22:04:50 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:50 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:50 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:50 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:50 DEBUG[5677] chan_sip.c: build_route: Contact hop: Sep 6 22:04:50 VERBOSE[5677] logger.c: list_route: hop: Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:50 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.52, port 5060 Sep 6 22:04:50 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.52:5060: ACK sip:1012@10.1.20.52:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK2987139a;rport From: ;tag=as3c4c872c To: "1012" ;tag=000af434e1311e717cfc5200-1296096d Contact: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: INVITE sip:1015@10.1.20.3:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK02d4fd5f From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as3c4c872c Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:16:06 GMT CSeq: 103 INVITE User-Agent: Cisco-CP7940G/7.5 Contact: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3:5060",response="ba76c997d937620af8c8aebc145352e2",nonce="4ab214da",algorithm=MD5 Content-Length: 251 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 27985 2 IN IP4 10.1.20.52 s=SIP Call t=0 0 m=audio 30648 RTP/AVP 8 0 18 101 c=IN IP4 10.1.20.52 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendonly Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: INVITE sip:1015@10.1.20.3:5060 SIP/2.0 (38) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK02d4fd5f (55) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: "1012" ;tag=000af434e1311e717cfc5200-1296096d (71) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=as3c4c872c (39) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:16:06 GMT (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: CSeq: 103 INVITE (16) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: Contact: (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes (101) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 11: Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3:5060",response="ba76c997d937620af8c8aebc145352e2",nonce="4ab214da",algorithm=MD5 (168) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 12: Content-Length: 251 (19) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 13: Content-Type: application/sdp (29) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 14: Content-Disposition: session;handling=optional (46) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 15: (0) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: o=Cisco-SIPUA 27985 2 IN IP4 10.1.20.52 (39) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: s=SIP Call (10) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: m=audio 30648 RTP/AVP 8 0 18 101 (32) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.52 (19) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=fmtp:101 0-15 (15) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=sendonly (10) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (15 headers 12 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (15 headers 12 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:58 DEBUG[5677] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Sep 6 22:04:58 VERBOSE[5677] logger.c: Using INVITE request as basis request - 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Sep 6 22:04:58 VERBOSE[5677] logger.c: Sending to 10.1.20.52 : 5060 (non-NAT) Sep 6 22:04:58 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found RTP audio format 0 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found RTP audio format 18 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:58 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.52:30648 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.52:30648 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:58 VERBOSE[5677] logger.c: Found description format PCMU Sep 6 22:04:58 VERBOSE[5677] logger.c: Found description format G729 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:58 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:58 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:58 DEBUG[5677] channel.c: Set channel SIP/1015-082a41c0 to write format slin Sep 6 22:04:58 VERBOSE[5677] logger.c: -- Started music on hold, class 'default', on channel 'SIP/1015-082a41c0' Sep 6 22:04:58 DEBUG[5677] channel.c: Scheduling timer at 160 sample intervals Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Got a SIP re-invite for call 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Sep 6 22:04:58 VERBOSE[5677] logger.c: We're at 10.1.20.3 port 16050 Sep 6 22:04:58 VERBOSE[5677] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:58 VERBOSE[5677] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:58 VERBOSE[5677] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK02d4fd5f;received=10.1.20.52 From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as3c4c872c Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 103 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 209 v=0 o=root 5662 5664 IN IP4 10.1.20.55 s=session c=IN IP4 10.1.20.55 t=0 0 m=audio 2226 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #144 Sep 6 22:04:58 DEBUG[5725] rtp.c: Oooh, 'SIP/1012-08294f30' changed end address to 0.0.0.0:0 (format 268) Sep 6 22:04:58 DEBUG[5725] rtp.c: Oooh, 'SIP/1012-08294f30' was 10.1.20.52:30648/(format 268) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Sending reinvite on SIP '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' - It's audio soon redirected to IP 10.1.20.3 Sep 6 22:04:58 VERBOSE[5725] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:58 VERBOSE[5725] logger.c: set_destination: set destination to 10.1.20.55, port 5060 Sep 6 22:04:58 VERBOSE[5725] logger.c: We're at 10.1.20.3 port 16036 Sep 6 22:04:58 VERBOSE[5725] logger.c: Adding codec 0x8 (alaw) to SDP Sep 6 22:04:58 VERBOSE[5725] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 0: INVITE sip:1015@10.1.20.55:5060 SIP/2.0 (39) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK096eebf2;rport (60) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 4: Contact: (29) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 6: CSeq: 104 INVITE (16) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (43) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 11: Content-Type: application/sdp (29) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 12: Content-Length: 208 (19) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Header 13: (0) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: v=0 (3) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: o=root 5662 5664 IN IP4 10.1.20.3 (33) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: s=session (9) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: c=IN IP4 10.1.20.3 (18) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: m=audio 16036 RTP/AVP 8 101 (27) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: a=fmtp:101 0-16 (15) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Line: a=silenceSupp:off - - - - (25) Sep 6 22:04:58 VERBOSE[5725] logger.c: 13 headers, 10 lines Sep 6 22:04:58 VERBOSE[5725] logger.c: Reliably Transmitting (no NAT) to 10.1.20.55:5060: INVITE sip:1015@10.1.20.55:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK096eebf2;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 Contact: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 CSeq: 104 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 208 v=0 o=root 5662 5664 IN IP4 10.1.20.3 s=session c=IN IP4 10.1.20.3 t=0 0 m=audio 16036 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 6 22:04:58 DEBUG[5725] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #145 Sep 6 22:04:58 DEBUG[5725] rtp.c: Difference is 58048, ms is 7276 Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.55:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK096eebf2;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 CSeq: 104 INVITE Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 Content-Type: application/sdp Content-Length: 183 v=0 o=- 1157576678 1157576680 IN IP4 10.1.20.55 s=Polycom IP Phone c=IN IP4 10.1.20.55 t=0 0 m=audio 2226 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK096eebf2;rport (60) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: "Walter McDonald" ;tag=as69758514 (59) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=50DE7C55-16E6E630 (52) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: CSeq: 104 INVITE (16) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 (51) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: Contact: (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_500-UA/1.6.7.0098 (54) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: Content-Type: application/sdp (29) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 10: Content-Length: 183 (19) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 11: (0) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: v=0 (3) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: o=- 1157576678 1157576680 IN IP4 10.1.20.55 (43) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: s=Polycom IP Phone (18) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: c=IN IP4 10.1.20.55 (19) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: t=0 0 (5) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: m=audio 2226 RTP/AVP 8 101 (26) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (11 headers 8 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (11 headers 8 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Acked pending invite 104 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #145 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Stopping retransmission on '0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3' of Request 104: Match Found Sep 6 22:04:58 DEBUG[5677] chan_sip.c: SIP response 200 to RE-invite on outgoing call 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found RTP audio format 8 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found RTP audio format 101 Sep 6 22:04:58 VERBOSE[5677] logger.c: Peer audio RTP is at port 10.1.20.55:2226 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Peer audio RTP is at port 10.1.20.55:2226 Sep 6 22:04:58 VERBOSE[5677] logger.c: Found description format PCMA Sep 6 22:04:58 VERBOSE[5677] logger.c: Found description format telephone-event Sep 6 22:04:58 VERBOSE[5677] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Sep 6 22:04:58 VERBOSE[5677] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: build_route: Retaining previous route: Sep 6 22:04:58 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:58 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.55, port 5060 Sep 6 22:04:58 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.55:5060: ACK sip:1015@10.1.20.55:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK0f698ed2;rport From: "Walter McDonald" ;tag=as69758514 To: ;tag=50DE7C55-16E6E630 Contact: Call-ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 CSeq: 104 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:58 DEBUG[5725] channel.c: Generator got voice, switching to phase locked mode Sep 6 22:04:58 DEBUG[5725] channel.c: Scheduling timer at 0 sample intervals Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: ACK sip:1015@10.1.20.3:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1a7a249c From: "1012" ;tag=000af434e1311e717cfc5200-1296096d To: ;tag=as3c4c872c Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:16:06 GMT CSeq: 103 ACK User-Agent: Cisco-CP7940G/7.5 Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3:5060",response="ba76c997d937620af8c8aebc145352e2",nonce="4ab214da",algorithm=MD5 Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: ACK sip:1015@10.1.20.3:5060 SIP/2.0 (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK1a7a249c (55) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: "1012" ;tag=000af434e1311e717cfc5200-1296096d (71) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=as3c4c872c (39) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:16:06 GMT (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: CSeq: 103 ACK (13) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: Proxy-Authorization: Digest username="1012",realm="phoneserver",uri="sip:1015@10.1.20.3:5060",response="ba76c997d937620af8c8aebc145352e2",nonce="4ab214da",algorithm=MD5 (168) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=calling;id-type=subscriber;privacy=off;screen=yes (101) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 12: (0) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (12 headers 0 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (12 headers 0 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:58 DEBUG[5677] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Sep 6 22:04:58 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #144 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Stopping retransmission on '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' of Response 103: Match Found Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: REFER sip:07966000000@10.1.20.3:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK094aadc5 From: ;tag=000af434e1311e7017d73770-41d2b9bd To: "->tests Oabcqfff" ;tag=as5b166e34 Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:16:06 GMT CSeq: 102 REFER User-Agent: Cisco-CP7940G/7.5 Contact: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 Refer-To: Referred-By: Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: REFER sip:07966000000@10.1.20.3:5060 SIP/2.0 (44) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK094aadc5 (55) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: ;tag=000af434e1311e7017d73770-41d2b9bd (81) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: "->tests Oabcqfff" ;tag=as5b166e34 (65) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Max-Forwards: 70 (16) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: Date: Wed, 06 Sep 2006 21:16:06 GMT (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: CSeq: 102 REFER (15) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: User-Agent: Cisco-CP7940G/7.5 (29) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: Contact: (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 10: Remote-Party-ID: "1012" ;party=called;id-type=subscriber;privacy=off;screen=yes (100) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 12: Refer-To: (157) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 13: Referred-By: (50) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 14: (0) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (14 headers 0 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (14 headers 0 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag DCE5A610-130B Our tag: as31597662 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: **** Received REFER (9) - Command in SIP REFER Sep 6 22:04:58 DEBUG[5677] chan_sip.c: SIP call transfer received for call 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (REFER)! Sep 6 22:04:58 VERBOSE[5677] logger.c: Transfer to 1015 in demo Sep 6 22:04:58 VERBOSE[5677] logger.c: Transfer from 1012 in demo Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Assigning Replace-Call-ID Info 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 to REPLACE_CALL_ID Sep 6 22:04:58 DEBUG[5677] chan_sip.c: 202 Accepted (supervised) Sep 6 22:04:58 DEBUG[5677] chan_agent.c: Asked for bridged channel on 'SIP/1012-08282898'/'Agent/2000', returning 'SIP/mags-0829c328' Sep 6 22:04:58 DEBUG[5677] channel.c: Set channel SIP/mags-0829c328 to write format alaw Sep 6 22:04:58 VERBOSE[5677] logger.c: -- Stopped music on hold on SIP/mags-0829c328 Sep 6 22:04:58 DEBUG[5677] channel.c: Scheduling timer at 0 sample intervals Sep 6 22:04:58 DEBUG[5677] channel.c: Set channel SIP/1015-082a41c0 to write format alaw Sep 6 22:04:58 VERBOSE[5677] logger.c: -- Stopped music on hold on SIP/1015-082a41c0 Sep 6 22:04:58 DEBUG[5677] channel.c: Scheduling timer at 0 sample intervals Sep 6 22:04:58 DEBUG[5677] chan_agent.c: Asked for bridged channel on 'SIP/mags-0829c328'/'Agent/2000', returning 'SIP/1012-08282898' Sep 6 22:04:58 DEBUG[5677] channel.c: Planning to masquerade channel Agent/2000 into the structure of SIP/1012-08294f30 Sep 6 22:04:58 DEBUG[5677] channel.c: Done planning to masquerade channel Agent/2000 into the structure of SIP/1012-08294f30 Sep 6 22:04:58 DEBUG[5725] channel.c: Actually Masquerading Agent/2000(6) into the structure of SIP/1012-08294f30(6) Sep 6 22:04:58 DEBUG[5725] channel.c: Got clone lock for masquerade on 'Agent/2000' at 0x81d46c4 Sep 6 22:04:58 VERBOSE[5677] logger.c: Transmitting (no NAT) to 10.1.20.52:5060: SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.1.20.52:5060;branch=z9hG4bK094aadc5;received=10.1.20.52 From: ;tag=000af434e1311e7017d73770-41d2b9bd To: "->tests Oabcqfff" ;tag=as5b166e34 Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 CSeq: 102 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Sep 6 22:04:58 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Hangup call Agent/2000, SIP callid 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52) Sep 6 22:04:58 DEBUG[5725] chan_sip.c: update_call_counter(1012) - decrement call limit counter Sep 6 22:04:58 DEBUG[5725] chan_sip.c: Updating call counter for incoming call Sep 6 22:04:58 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.52, port 5060 Sep 6 22:04:58 VERBOSE[5725] logger.c: Scheduling destruction of call '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' in 32000 ms Sep 6 22:04:58 VERBOSE[5677] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: NOTIFY sip:1012@10.1.20.52:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK40ea3fbc;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Contact: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 CSeq: 103 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=102 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Content-Length: 14 SIP/2.0 200 OK --- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #147 Sep 6 22:04:58 VERBOSE[5725] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:58 VERBOSE[5677] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:58 VERBOSE[5725] logger.c: set_destination: set destination to 10.1.20.52, port 5060 Sep 6 22:04:58 VERBOSE[5677] logger.c: set_destination: set destination to 10.1.20.52, port 5060 Sep 6 22:04:58 VERBOSE[5725] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: BYE sip:1012@10.1.20.52:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK0a5d3645;rport From: ;tag=as3c4c872c To: "1012" ;tag=000af434e1311e717cfc5200-1296096d Contact: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:58 DEBUG[5725] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #148 Sep 6 22:04:58 DEBUG[5725] channel.c: Putting channel Agent/2000 in 8/8 formats Sep 6 22:04:58 VERBOSE[5677] logger.c: Reliably Transmitting (no NAT) to 10.1.20.52:5060: BYE sip:1012@10.1.20.52:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK599be525;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Contact: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 CSeq: 104 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 6 22:04:58 DEBUG[5725] channel.c: Released clone lock on 'SIP/1012-08294f30' Sep 6 22:04:58 DEBUG[5713] channel.c: Didn't get a frame from channel: SIP/1012-08294f30 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #149 Sep 6 22:04:58 DEBUG[5713] channel.c: Bridge stops bridging channels SIP/1012-08294f30 and SIP/mags-0829c328 Sep 6 22:04:58 DEBUG[5713] channel.c: Hanging up channel 'SIP/mags-0829c328' Sep 6 22:04:58 DEBUG[5713] chan_sip.c: Hangup call SIP/mags-0829c328, SIP callid 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net) Sep 6 22:04:58 DEBUG[5713] chan_sip.c: update_call_counter(447966000000) - decrement call limit counter Sep 6 22:04:58 DEBUG[5713] chan_sip.c: Updating call counter for outgoing call Sep 6 22:04:58 VERBOSE[5713] logger.c: Scheduling destruction of call '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' in 32000 ms Sep 6 22:04:58 VERBOSE[5713] logger.c: set_destination: Parsing for address/port to send to Sep 6 22:04:58 VERBOSE[5713] logger.c: set_destination: set destination to 213.166.5.135, port 5060 Sep 6 22:04:58 DEBUG[5725] channel.c: Done Masquerading Agent/2000 (6) Sep 6 22:04:58 DEBUG[5725] rtp.c: Oooh, something is weird, backing out Sep 6 22:04:58 VERBOSE[5713] logger.c: Reliably Transmitting (NAT) to 213.166.5.135:5060: BYE sip:00447966000000@213.166.5.133:5060 SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK64c915f3;rport Route: From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=DCE5A610-130B Contact: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net CSeq: 104 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Proxy-Authorization: Digest username="fullcircle", realm="gk.magrathea.net", algorithm=MD5, uri="sip:00447966000000@213.166.5.133:5060", nonce="44ff391d2a72048a356ed2e33c1a30c353ab4692", response="e955806191e0a1f244fa7c49c85e0ede", opaque="" Content-Length: 0 --- Sep 6 22:04:58 DEBUG[5713] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #151 Sep 6 22:04:58 DEBUG[5713] app_dial.c: Exiting with DIALSTATUS=ANSWER. Sep 6 22:04:58 DEBUG[5666] chan_sip.c: Checking device state for peer mags Sep 6 22:04:58 DEBUG[5713] pbx.c: Spawn extension (auto_dial,07966000000,8) exited non-zero on 'SIP/1012-08294f30' Sep 6 22:04:58 DEBUG[5666] devicestate.c: Changing state for SIP/mags - state 1 (Not in use) Sep 6 22:04:58 DEBUG[5713] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. Sep 6 22:04:58 DEBUG[5730] app_queue.c: Device 'SIP/mags' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 6 22:04:58 DEBUG[5713] cdr_pgsql.c: cdr_pgsql: SQL command executed: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2006-09-06 22:04:31','"Walter McDonald" <2000>','2000','07966000000','auto_dial', 'Agent/2000','SIP/mags-0829c328','Dial','SIP/447966000000@mags',27,19,'ANSWERED',3,'test','1157576670.3','000/agent-2000-o2c177331-20060906-220431.gsm') Sep 6 22:04:58 DEBUG[5713] channel.c: Hanging up zombie 'SIP/1012-08294f30' Sep 6 22:04:58 NOTICE[5713] pbx_spool.c: Call completed to AGENT/2000 Sep 6 22:04:58 DEBUG[5666] chan_sip.c: Checking device state for peer 1012 Sep 6 22:04:58 DEBUG[5666] devicestate.c: Changing state for SIP/1012 - state 2 (In use) Sep 6 22:04:58 DEBUG[5731] app_queue.c: Device 'SIP/1012' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK64c915f3;rport=5060 From: "->tests Oabcqfff" ;tag=as31597662 To: ;tag=DCE5A610-130B Date: Wed, 06 Sep 2006 21:04:58 gmt Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 CSeq: 104 BYE Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK64c915f3;rport=5060 (69) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as31597662 (73) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=DCE5A610-130B (57) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Date: Wed, 06 Sep 2006 21:04:58 gmt (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net (58) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: Content-Length: 0 (17) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: CSeq: 104 BYE (13) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: (0) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (9 headers 0 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (9 headers 0 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net Their Tag DCE5A610-130B Our tag: as31597662 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #151 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Stopping retransmission on '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' of Request 104: Match Found Sep 6 22:04:58 VERBOSE[5677] logger.c: Destroying call '544a40d10bb3132533c3d45c0fb7dc85@gk.magrathea.net' Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:52242: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK40ea3fbc;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Date: Wed, 06 Sep 2006 21:16:06 GMT CSeq: 103 NOTIFY Content-Length: 0 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK40ea3fbc;rport (60) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as5b166e34 (67) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=000af434e1311e7017d73770-41d2b9bd (79) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:16:06 GMT (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: CSeq: 103 NOTIFY (16) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: Content-Length: 0 (17) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: (0) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (8 headers 0 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (8 headers 0 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #147 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Stopping retransmission on '265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3' of Request 103: Match Found Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK0a5d3645;rport From: ;tag=as3c4c872c To: "1012" ;tag=000af434e1311e717cfc5200-1296096d Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Date: Wed, 06 Sep 2006 21:16:06 GMT CSeq: 103 BYE Server: Cisco-CP7940G/7.5 Content-Length: 0 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK0a5d3645;rport (60) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: ;tag=as3c4c872c (41) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: "1012" ;tag=000af434e1311e717cfc5200-1296096d (69) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 (55) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:16:06 GMT (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: CSeq: 103 BYE (13) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: Server: Cisco-CP7940G/7.5 (25) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: Content-Length: 0 (17) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: (0) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (9 headers 0 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (9 headers 0 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52 Their Tag 000af434e1311e717cfc5200-1296096d Our tag: as3c4c872c Sep 6 22:04:58 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #148 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Stopping retransmission on '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' of Request 103: Match Found Sep 6 22:04:58 VERBOSE[5677] logger.c: Destroying call '000af434-e131070d-07ac1191-17d0aa0f@10.1.20.52' Sep 6 22:04:58 VERBOSE[5677] logger.c: <-- SIP read from 10.1.20.52:50366: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK599be525;rport From: "->tests Oabcqfff" ;tag=as5b166e34 To: ;tag=000af434e1311e7017d73770-41d2b9bd Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Date: Wed, 06 Sep 2006 21:16:06 GMT CSeq: 104 BYE Server: Cisco-CP7940G/7.5 Content-Length: 0 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.1.20.3:5060;branch=z9hG4bK599be525;rport (60) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 2: From: "->tests Oabcqfff" ;tag=as5b166e34 (67) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=000af434e1311e7017d73770-41d2b9bd (79) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 (51) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 5: Date: Wed, 06 Sep 2006 21:16:06 GMT (35) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 6: CSeq: 104 BYE (13) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 7: Server: Cisco-CP7940G/7.5 (25) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 8: Content-Length: 0 (17) Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Header 9: (0) Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (9 headers 0 lines)Sep 6 22:04:58 VERBOSE[5677] logger.c: --- (9 headers 0 lines)--- Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = No match Their Call ID: 0ebf3ef418f583db5c16e4264958d4d9@10.1.20.3 Their Tag 50DE7C55-16E6E630 Our tag: as69758514 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: = Found Their Call ID: 265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3 Their Tag 000af434e1311e7017d73770-41d2b9bd Our tag: as5b166e34 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #149 Sep 6 22:04:58 DEBUG[5677] chan_sip.c: Stopping retransmission on '265f5e481cf3504b4f47ae1351a1abaa@10.1.20.3' of Request 104: Match Found Sep 6 22:05:00 DEBUG[5725] rtp.c: Got RTCP report of 76 bytes Sep 6 22:05:10 DEBUG[5725] rtp.c: Got RTCP report of 76 bytes Sep 6 22:05:20 DEBUG[5725] rtp.c: Got RTCP report of 76 bytes Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Sep 6 22:05:30 DEBUG[5677] acl.c: ##### Testing 213.166.5.135 with 10.1.20.0 Sep 6 22:05:30 DEBUG[5677] acl.c: ##### Testing 213.166.5.135 with 172.28.1.0 Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Target address 213.166.5.135 is not local, substituting externip Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 0: OPTIONS sip:gk.magrathea.net SIP/2.0 (36) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK04395df3;rport (64) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 2: From: "asterisk" ;tag=as5a4146a3 (60) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 3: To: (26) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 4: Contact: (37) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 5: Call-ID: 23253987401889d20f6037e56101e38f@89.105.104.74 (55) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 8: Max-Forwards: 70 (16) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 9: Date: Wed, 06 Sep 2006 21:05:30 GMT (35) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 11: Content-Length: 0 (17) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 12: (0) Sep 6 22:05:30 VERBOSE[5677] logger.c: 12 headers, 0 lines Sep 6 22:05:30 VERBOSE[5677] logger.c: Reliably Transmitting (NAT) to 213.166.5.135:5060: OPTIONS sip:gk.magrathea.net SIP/2.0 Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK04395df3;rport From: "asterisk" ;tag=as5a4146a3 To: Contact: Call-ID: 23253987401889d20f6037e56101e38f@89.105.104.74 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 06 Sep 2006 21:05:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- Sep 6 22:05:30 DEBUG[5677] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #152 Sep 6 22:05:30 VERBOSE[5677] logger.c: <-- SIP read from 213.166.5.135:5060: SIP/2.0 403 OPTIONS not supported Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK04395df3;rport=5060 From: "asterisk" ;tag=as5a4146a3 To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.e513 Call-ID: 23253987401889d20f6037e56101e38f@89.105.104.74 CSeq: 102 OPTIONS Server: Sip EXpress router (0.8.99-dev (i386/linux)) Content-Length: 0 Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 0: SIP/2.0 403 OPTIONS not supported (33) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 1: Via: SIP/2.0/UDP 89.105.104.74:5060;branch=z9hG4bK04395df3;rport=5060 (69) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 2: From: "asterisk" ;tag=as5a4146a3 (60) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 3: To: ;tag=a3e149d53f0faf6bf88ecc254282dfd9.e513 (68) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 4: Call-ID: 23253987401889d20f6037e56101e38f@89.105.104.74 (55) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 6: Server: Sip EXpress router (0.8.99-dev (i386/linux)) (52) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 7: Content-Length: 0 (17) Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Header 8: (0) Sep 6 22:05:30 VERBOSE[5677] logger.c: --- (8 headers 0 lines)Sep 6 22:05:30 VERBOSE[5677] logger.c: --- (8 headers 0 lines)--- Sep 6 22:05:30 DEBUG[5677] chan_sip.c: = Found Their Call ID: 23253987401889d20f6037e56101e38f@89.105.104.74 Their Tag Our tag: as5a4146a3 Sep 6 22:05:30 DEBUG[5677] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #152 Sep 6 22:05:30 DEBUG[5677] chan_sip.c: Stopping retransmission on '23253987401889d20f6037e56101e38f@89.105.104.74' of Request 102: Match Found Sep 6 22:05:30 VERBOSE[5677] logger.c: Destroying call '23253987401889d20f6037e56101e38f@89.105.104.74' Sep 6 22:05:30 DEBUG[5682] chan_iax2.c: Peer lastms 18, historicms 18, maxms 120 Sep 6 22:05:30 DEBUG[5725] rtp.c: Got RTCP report of 76 bytes