Asterisk Ready. *CLI> sip debug SIP Debugging enabled *CLI> <-- SIP read from 192.168.1.97:45864: REGISTER sip:192.168.1.90 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bKDF9C073F07B34FEC88645D4C92F46B8E From: 151 To: 151 Contact: "151" Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 CSeq: 44891 REGISTER Expires: 1800 Max-Forwards: 70 User-Agent: X-PRO build 1082 Content-Length: 0 [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: REGISTER sip:192.168.1.90 SIP/2.0 (33) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bKDF9C073F07B34FEC88645D4C92F46B8E (88) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: 151 (32) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: 151 (30) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: "151" (43) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 (54) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 44891 REGISTER (20) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Expires: 1800 (13) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: User-Agent: X-PRO build 1082 (28) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Content-Length: 0 (17) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: (0) --- (11 headers 0 lines)--- [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 - REGISTER (No RTP) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:13052 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 192.168.1.97 : 45864 (NAT) Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bKDF9C073F07B34FEC88645D4C92F46B8E;received=192.168.1.97 From: 151 To: 151 Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 CSeq: 44891 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bKDF9C073F07B34FEC88645D4C92F46B8E;received=192.168.1.97 From: 151 To: 151 ;tag=as4c5dad92 Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 CSeq: 44891 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: WWW-Authenticate: Digest realm="kb-serge-laptop.katherinebishop.com", nonce="25b445fc" Content-Length: 0 --- Scheduling destruction of SIP dialog '6CE0E824737A45A8AB21B087665B494A@192.168.1.90' in 32000 ms (Method: REGISTER) <-- SIP read from 192.168.1.97:45864: REGISTER sip:192.168.1.90 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK038C239CC62C41BD9E1A111A66648285 From: 151 To: 151 Contact: "151" Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 CSeq: 44892 REGISTER Expires: 1800 Authorization: Digest username="151",realm="kb-serge-laptop.katherinebishop.com",nonce="25b445fc",response="dfbbad28434ca9bbf3ee3a2f206ccf6c",uri="sip:192.168.1.90" Max-Forwards: 70 User-Agent: X-PRO build 1082 Content-Length: 0 [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: REGISTER sip:192.168.1.90 SIP/2.0 (33) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK038C239CC62C41BD9E1A111A66648285 (88) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: 151 (32) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: 151 (30) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: "151" (43) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 (54) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 44892 REGISTER (20) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Expires: 1800 (13) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Authorization: Digest username="151",realm="kb-serge-laptop.katherinebishop.com",nonce="25b445fc",response="dfbbad28434ca9bbf3ee3a2f206ccf6c",uri="sip:192.168.1.90" (164) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Max-Forwards: 70 (16) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: User-Agent: X-PRO build 1082 (28) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: Content-Length: 0 (17) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 12: (0) --- (12 headers 0 lines)--- [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 Their Tag Our tag: as4c5dad92 [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:13052 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 192.168.1.97 : 45864 (NAT) Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK038C239CC62C41BD9E1A111A66648285;received=192.168.1.97 From: 151 To: 151 Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 CSeq: 44892 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 (42) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK17f30a1c;rport (63) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "asterisk" ;tag=as4d006cba (59) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (32) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (36) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 (54) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Date: Mon, 12 Jun 2006 16:15:16 GMT (35) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: Supported: replaces (19) [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK17f30a1c;rport From: "asterisk" ;tag=as4d006cba To: Contact: Call-ID: 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:16 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:16] DEBUG[27939]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #10 -- Registered SIP '151' at 192.168.1.97 port 45864 expires 1800 -- Saved useragent "X-PRO build 1082" for peer 151 Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK038C239CC62C41BD9E1A111A66648285;received=192.168.1.97 From: 151 To: 151 ;tag=as4c5dad92 Call-ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 CSeq: 44892 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 1800 Contact: ;expires=1800 Date: Mon, 12 Jun 2006 16:15:16 GMT Content-Length: 0 --- Scheduling destruction of SIP dialog '6CE0E824737A45A8AB21B087665B494A@192.168.1.90' in 15000 ms (Method: REGISTER) [Jun 12 12:15:16] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:16] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) [Jun 12 12:15:17] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #10:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK17f30a1c;rport From: "asterisk" ;tag=as4d006cba To: Contact: Call-ID: 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:16 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:18] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #10:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK17f30a1c;rport From: "asterisk" ;tag=as4d006cba To: Contact: Call-ID: 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:16 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:19] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #10:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK17f30a1c;rport From: "asterisk" ;tag=as4d006cba To: Contact: Call-ID: 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:16 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:20] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #10:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK17f30a1c;rport From: "asterisk" ;tag=as4d006cba To: Contact: Call-ID: 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:16 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:20] NOTICE[27939]: chan_sip.c:13505 sip_poke_noanswer: Peer '151' is now UNREACHABLE! Last qualify: 0 [Jun 12 12:15:20] DEBUG[27939]: chan_sip.c:2701 sip_destroy: Destroying SIP dialog 090cae8455cb3ecb65045cd23d5c52af@192.168.1.92 Really destroying SIP dialog '090cae8455cb3ecb65045cd23d5c52af@192.168.1.92' Method: OPTIONS [Jun 12 12:15:20] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:20] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) <-- SIP read from 192.168.1.97:45864: INVITE sip:108@192.168.1.90 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK727E13AE345D4B63997602E5D2845E5D From: 151 ;tag=194809670 To: Contact: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26482 INVITE Max-Forwards: 70 Content-Type: application/sdp User-Agent: X-PRO build 1082 Content-Length: 271 v=0 o=151 2711192265 2711192265 IN IP4 192.168.1.97 s=X-PRO c=IN IP4 192.168.1.97 t=0 0 m=audio 45866 RTP/AVP 0 3 18 98 101 a=rtpmap:0 pcmu/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 G729/8000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: INVITE sip:108@192.168.1.90 SIP/2.0 (35) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK727E13AE345D4B63997602E5D2845E5D (88) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: 151 ;tag=194809670 (46) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (26) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (37) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 (58) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 26482 INVITE (18) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Max-Forwards: 70 (16) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Content-Type: application/sdp (29) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: User-Agent: X-PRO build 1082 (28) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Content-Length: 271 (19) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: (0) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: v=0 (3) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: o=151 2711192265 2711192265 IN IP4 192.168.1.97 (47) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: s=X-PRO (7) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: c=IN IP4 192.168.1.97 (21) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: t=0 0 (5) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: m=audio 45866 RTP/AVP 0 3 18 98 101 (35) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=fmtp:101 0-15 (15) --- (11 headers 12 lines)--- [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3799 find_call: = No match Their Call ID: 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 Their Tag Our tag: as4c5dad92 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 - INVITE (With RTP) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:13052 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.1.97 : 45864 (NAT) Using INVITE request as basis request - 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:7900 check_user_full: Setting NAT on RTP to Off Reliably Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK727E13AE345D4B63997602E5D2845E5D;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as19239dbd Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26482 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Proxy-Authenticate: Digest realm="kb-serge-laptop.katherinebishop.com", nonce="337369e3" Content-Length: 0 --- [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #14 Scheduling destruction of SIP dialog '0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97' in 32000 ms (Method: INVITE) Found user '151' <-- SIP read from 192.168.1.97:45864: ACK sip:108@192.168.1.90 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK727E13AE345D4B63997602E5D2845E5D From: 151 ;tag=194809670 To: ;tag=as19239dbd Contact: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26482 ACK Max-Forwards: 70 Content-Length: 0 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: ACK sip:108@192.168.1.90 SIP/2.0 (32) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK727E13AE345D4B63997602E5D2845E5D (88) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: 151 ;tag=194809670 (46) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: ;tag=as19239dbd (41) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (37) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 (58) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 26482 ACK (15) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Max-Forwards: 70 (16) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Content-Length: 0 (17) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 Their Tag 194809670 Our tag: as19239dbd [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:13052 handle_request: **** Received ACK (6) - Command in SIP ACK [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:1761 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:1771 __sip_ack: Stopping retransmission on '0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97' of Response 26482: Match Not Found <-- SIP read from 192.168.1.97:45864: INVITE sip:108@192.168.1.90 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90 From: 151 ;tag=194809670 To: Contact: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE Proxy-Authorization: Digest username="151",realm="kb-serge-laptop.katherinebishop.com",nonce="337369e3",response="56b47d62bfb1022d52994dac6489b42d",uri="sip:108@192.168.1.90" Max-Forwards: 70 Content-Type: application/sdp User-Agent: X-PRO build 1082 Content-Length: 271 v=0 o=151 2711192281 2711192281 IN IP4 192.168.1.97 s=X-PRO c=IN IP4 192.168.1.97 t=0 0 m=audio 45866 RTP/AVP 0 3 18 98 101 a=rtpmap:0 pcmu/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 G729/8000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: INVITE sip:108@192.168.1.90 SIP/2.0 (35) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90 (88) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: 151 ;tag=194809670 (46) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (26) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (37) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 (58) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 26483 INVITE (18) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Proxy-Authorization: Digest username="151",realm="kb-serge-laptop.katherinebishop.com",nonce="337369e3",response="56b47d62bfb1022d52994dac6489b42d",uri="sip:108@192.168.1.90" (174) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Content-Type: application/sdp (29) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: User-Agent: X-PRO build 1082 (28) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: Content-Length: 271 (19) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 12: (0) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: v=0 (3) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: o=151 2711192281 2711192281 IN IP4 192.168.1.97 (47) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: s=X-PRO (7) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: c=IN IP4 192.168.1.97 (21) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: t=0 0 (5) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: m=audio 45866 RTP/AVP 0 3 18 98 101 (35) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=fmtp:101 0-15 (15) --- (12 headers 12 lines)--- [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 Their Tag 194809670 Our tag: as19239dbd [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:13052 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.1.97 : 45864 (NAT) Using INVITE request as basis request - 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:7900 check_user_full: Setting NAT on RTP to Off Found user '151' Found RTP audio format 0 Found RTP audio format 3 Found RTP audio format 18 Found RTP audio format 98 Found RTP audio format 101 Found description format rtpmap:0 pcmu/8000 for ID 101 Found description format rtpmap:3 gsm/8000 for ID 101 Found description format rtpmap:18 G729/8000 for ID 101 Found description format rtpmap:98 iLBC/8000 for ID 101 Found description format rtpmap:101 telephone-event/8000 for ID 101 Got unsupported a:fmtp in SDP offer Capabilities: us - 0x80406 (gsm|ulaw|ilbc|h263), peer - audio=0x3d07ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|jpeg|h261|h263|h263p|h264)/video=0x3d07ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|jpeg|h261|h263|h263p|h264), combined - 0x80406 (gsm|ulaw|ilbc|h263) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.97:45866 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:4386 process_sdp: We're settling with these formats: 0x80406 (gsm|ulaw|ilbc|h263) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:11964 handle_request_invite: Checking SIP call limits for device 151 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:2595 update_call_counter: Updating call counter for incoming call Looking for 108 in ldaccess (domain 192.168.1.90) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3299 sip_new: *** Our native formats are 0x80002 (gsm|h263) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3300 sip_new: *** Joint capabilities are 0x80406 (gsm|ulaw|ilbc|h263) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3301 sip_new: *** Our capabilities are 0x80406 (gsm|ulaw|ilbc|h263) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3302 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3325 sip_new: This channel will not be able to handle video. [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:6873 build_route: build_route: Contact hop: list_route: hop: [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:12034 handle_request_invite: SIP/151-61b0: New call is still down.... Trying... Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Jun 12 12:15:25] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:25] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) [Jun 12 12:15:25] DEBUG[27954]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [108@ldaccess:1] Macro("SIP/151-61b0", "stdexten|108|SIP/108") in new stack [Jun 12 12:15:25] DEBUG[27954]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-stdexten:1] NoOp("SIP/151-61b0", "extension s@192.168.1.90") in new stack [Jun 12 12:15:25] DEBUG[27954]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-stdexten:2] Dial("SIP/151-61b0", "SIP/108|20") in new stack [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:13675 sip_request_call: Asked to create a SIP channel with formats: 0x80002 (gsm|h263) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:2245 create_addr_from_peer: Setting NAT on RTP to Off [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3299 sip_new: *** Our native formats are 0x2 (gsm) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3300 sip_new: *** Joint capabilities are 0x0 (nothing) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3301 sip_new: *** Our capabilities are 0x80406 (gsm|ulaw|ilbc|h263) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3302 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3304 sip_new: *** Our preferred formats from the incoming channel are 0x80002 (gsm|h263) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3325 sip_new: This channel will not be able to handle video. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-2. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable ARG2. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable ARG1. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable STACK-ldaccess-108-1. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jun 12 12:15:25] DEBUG[27954]: channel.c:2919 ast_channel_inherit_variables: Not copying variable SIPURI. [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:2437 sip_call: Outgoing Call for 108 [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:2595 update_call_counter: Updating call counter for outgoing call [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5147 add_sdp: ** Our capability: 0x80406 (gsm|ulaw|ilbc|h263) Video flag: False [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5148 add_sdp: ** Our prefcodec: 0x80002 (gsm|h263) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5158 add_sdp: This call needs video offers, but there's no video support enabled ! Audio is at 192.168.1.92 port 15488 Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5293 add_sdp: -- Done with adding codecs to SDP [Jun 12 12:15:25] DEBUG[27954]: channel.c:2105 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5332 add_sdp: Done building SDP. Settling with this capability: 0x80406 (gsm|ulaw|ilbc|h263) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 0: INVITE sip:108@192.168.1.108:5060 SIP/2.0 (41) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport (63) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 2: From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 (71) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 3: To: (32) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 4: Contact: (31) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 (54) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 INVITE (16) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 9: Date: Mon, 12 Jun 2006 16:15:25 GMT (35) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 11: Supported: replaces (19) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 12: Content-Type: application/sdp (29) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 13: Content-Length: 277 (19) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:3971 parse_request: Header 14: (0) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: v=0 (3) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: o=root 27932 27932 IN IP4 192.168.1.92 (38) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: s=session (9) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: c=IN IP4 192.168.1.92 (21) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: t=0 0 (5) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: m=audio 15488 RTP/AVP 3 0 97 101 (32) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=fmtp:101 0-16 (15) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=silenceSupp:off - - - - (25) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:4003 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 192.168.1.108:5060: INVITE sip:108@192.168.1.108:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: Contact: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27932 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 15488 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #16 -- Called 108 [Jun 12 12:15:25] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/108-1b73 to read format gsm [Jun 12 12:15:25] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/151-61b0 to write format gsm [Jun 12 12:15:25] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/151-61b0 to read format gsm [Jun 12 12:15:25] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/108-1b73 to write format gsm <-- SIP read from 192.168.1.108:52022: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport;received=192.168.1.90 From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Date: Mon, 12 Jun 2006 16:15:25 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport;received=192.168.1.90 (85) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 (71) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (32) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 (54) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Date: Mon, 12 Jun 2006 16:15:25 GMT (35) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 INVITE (16) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Server: CSCO/7 (14) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Contact: (37) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Content-Length: 0 (17) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Their Tag Our tag: as7ad6dd32 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:1804 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #16 - INVITE (got response) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:1813 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '15180d7b10f9a8db409fff092b76491b@192.168.1.92' Request 102: Found [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:10411 handle_response_invite: SIP response 100 to standard invite <-- SIP read from 192.168.1.97:45864: [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- <-- SIP read from 192.168.1.108:52023: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport;received=192.168.1.90 From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: ;tag=001201b3355000495e771a50-746b4f85 Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Date: Mon, 12 Jun 2006 16:15:25 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport;received=192.168.1.90 (85) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 (71) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: ;tag=001201b3355000495e771a50-746b4f85 (70) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 (54) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Date: Mon, 12 Jun 2006 16:15:25 GMT (35) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 INVITE (16) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Server: CSCO/7 (14) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Contact: (37) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Content-Length: 0 (17) [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Their Tag Our tag: as7ad6dd32 [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:1813 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '15180d7b10f9a8db409fff092b76491b@192.168.1.92' Request 102: Found [Jun 12 12:15:25] DEBUG[27939]: chan_sip.c:10411 handle_response_invite: SIP response 180 to standard invite -- SIP/108-1b73 is ringing Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Jun 12 12:15:25] DEBUG[27954]: channel.c:2158 ast_indicate_data: Driver for channel 'SIP/151-61b0' does not support indication 3, emulating it [Jun 12 12:15:25] DEBUG[27954]: channel.c:2288 ast_prod: Prodding channel 'SIP/151-61b0' [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5147 add_sdp: ** Our capability: 0x80406 (gsm|ulaw|ilbc|h263) Video flag: True [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5148 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.1.92 port 12992 Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5293 add_sdp: -- Done with adding codecs to SDP [Jun 12 12:15:25] DEBUG[27954]: channel.c:2105 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 12 12:15:25] DEBUG[27954]: chan_sip.c:5332 add_sdp: Done building SDP. Settling with this capability: 0x80406 (gsm|ulaw|ilbc|h263) Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27932 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:25] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/151-61b0 to write format slin [Jun 12 12:15:25] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 108 [Jun 12 12:15:25] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/108 - state 1 (Not in use) [Jun 12 12:15:26] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Jun 12 12:15:26] DEBUG[27939]: chan_sip.c:2701 sip_destroy: Destroying SIP dialog 193cefe63ea8636c4f45a3934a187809@192.168.1.92 Really destroying SIP dialog '193cefe63ea8636c4f45a3934a187809@192.168.1.92' Method: NOTIFY <-- SIP read from 192.168.1.108:52024: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport;received=192.168.1.90 From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: ;tag=001201b3355000495e771a50-746b4f85 Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Date: Mon, 12 Jun 2006 16:15:29 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 197 v=0 o=Cisco-SIPUA 17006 156 IN IP4 192.168.1.108 s=SIP Call c=IN IP4 192.168.1.108 t=0 0 m=audio 24826 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: SIP/2.0 200 OK (14) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK704c494d;rport;received=192.168.1.90 (85) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 (71) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: ;tag=001201b3355000495e771a50-746b4f85 (70) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 (54) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Date: Mon, 12 Jun 2006 16:15:29 GMT (35) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 INVITE (16) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Server: CSCO/7 (14) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Contact: (37) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Content-Type: application/sdp (29) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Content-Length: 197 (19) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: (0) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: v=0 (3) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: o=Cisco-SIPUA 17006 156 IN IP4 192.168.1.108 (44) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: s=SIP Call (10) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: c=IN IP4 192.168.1.108 (22) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: t=0 0 (5) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: m=audio 24826 RTP/AVP 0 101 (27) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=fmtp:101 0-15 (15) --- (11 headers 9 lines)--- [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Their Tag 001201b3355000495e771a50-746b4f85 Our tag: as7ad6dd32 [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:1753 __sip_ack: Acked pending invite 102 [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:1771 __sip_ack: Stopping retransmission on '15180d7b10f9a8db409fff092b76491b@192.168.1.92' of Request 102: Match Not Found [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:10411 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Found description format rtpmap:0 PCMU/8000 for ID 101 Found description format rtpmap:101 telephone-event/8000 for ID 101 Got unsupported a:fmtp in SDP offer Capabilities: us - 0x80406 (gsm|ulaw|ilbc|h263), peer - audio=0x3d07ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|jpeg|h261|h263|h263p|h264)/video=0x3d07ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|jpeg|h261|h263|h263p|h264), combined - 0x80406 (gsm|ulaw|ilbc|h263) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.108:24826 [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4386 process_sdp: We're settling with these formats: 0x80406 (gsm|ulaw|ilbc|h263) [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:2595 update_call_counter: Updating call counter for outgoing call [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:6873 build_route: build_route: Contact hop: list_route: hop: [Jun 12 12:15:29] DEBUG[27939]: chan_sip.c:4818 reqprep: Strict routing enforced for session 15180d7b10f9a8db409fff092b76491b@192.168.1.92 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.108, port 5060 Transmitting (no NAT) to 192.168.1.108:5060: ACK sip:108@192.168.1.108:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK45b80aeb;rport From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: ;tag=001201b3355000495e771a50-746b4f85 Contact: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- SIP/108-1b73 answered SIP/151-61b0 [Jun 12 12:15:29] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/151-61b0 to write format gsm [Jun 12 12:15:29] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/151-61b0 to read format gsm [Jun 12 12:15:29] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/108-1b73 to write format gsm [Jun 12 12:15:29] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/108-1b73 to read format gsm [Jun 12 12:15:29] DEBUG[27954]: channel.c:2474 set_format: Set channel SIP/151-61b0 to write format gsm [Jun 12 12:15:29] DEBUG[27954]: chan_sip.c:3017 sip_answer: SIP answering channel: SIP/151-61b0 [Jun 12 12:15:29] DEBUG[27954]: chan_sip.c:5147 add_sdp: ** Our capability: 0x80406 (gsm|ulaw|ilbc|h263) Video flag: True [Jun 12 12:15:29] DEBUG[27954]: chan_sip.c:5148 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.1.92 port 12992 Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jun 12 12:15:29] DEBUG[27954]: chan_sip.c:5293 add_sdp: -- Done with adding codecs to SDP [Jun 12 12:15:29] DEBUG[27954]: channel.c:2105 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 12 12:15:29] DEBUG[27954]: chan_sip.c:5332 add_sdp: Done building SDP. Settling with this capability: 0x80406 (gsm|ulaw|ilbc|h263) Reliably Transmitting (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:29] DEBUG[27954]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #18 [Jun 12 12:15:29] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 108 [Jun 12 12:15:29] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/108 - state 1 (Not in use) [Jun 12 12:15:29] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:29] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:1565 retrans_pkt: SIP TIMER: Rescheduling retransmission #18 (1) SIP/2.0 - 1 [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:1579 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #18)) Retransmitting #1 (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 (42) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK2fff3c04;rport (63) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "asterisk" ;tag=as1d93d0fd (59) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (32) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (36) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 (54) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Date: Mon, 12 Jun 2006 16:15:30 GMT (35) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: Supported: replaces (19) [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK2fff3c04;rport From: "asterisk" ;tag=as1d93d0fd To: Contact: Call-ID: 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:30] DEBUG[27939]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #19 [Jun 12 12:15:31] DEBUG[27939]: chan_sip.c:1565 retrans_pkt: SIP TIMER: Rescheduling retransmission #18 (2) SIP/2.0 - 1 [Jun 12 12:15:31] DEBUG[27939]: chan_sip.c:1579 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #18)) Retransmitting #2 (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:31] DEBUG[27939]: chan_sip.c:1702 __sip_autodestruct: Auto destroying call '6CE0E824737A45A8AB21B087665B494A@192.168.1.90' [Jun 12 12:15:31] DEBUG[27939]: chan_sip.c:2701 sip_destroy: Destroying SIP dialog 6CE0E824737A45A8AB21B087665B494A@192.168.1.90 Really destroying SIP dialog '6CE0E824737A45A8AB21B087665B494A@192.168.1.90' Method: REGISTER [Jun 12 12:15:31] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #19:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK2fff3c04;rport From: "asterisk" ;tag=as1d93d0fd To: Contact: Call-ID: 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:32] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #19:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK2fff3c04;rport From: "asterisk" ;tag=as1d93d0fd To: Contact: Call-ID: 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:33] DEBUG[27939]: chan_sip.c:1565 retrans_pkt: SIP TIMER: Rescheduling retransmission #18 (3) SIP/2.0 - 1 [Jun 12 12:15:33] DEBUG[27939]: chan_sip.c:1579 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #18)) Retransmitting #3 (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:33] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #19:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK2fff3c04;rport From: "asterisk" ;tag=as1d93d0fd To: Contact: Call-ID: 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:34] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #19:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK2fff3c04;rport From: "asterisk" ;tag=as1d93d0fd To: Contact: Call-ID: 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:34] DEBUG[27939]: chan_sip.c:2701 sip_destroy: Destroying SIP dialog 4f434aeb156384ac14ff85b56e56ae16@192.168.1.92 Really destroying SIP dialog '4f434aeb156384ac14ff85b56e56ae16@192.168.1.92' Method: OPTIONS [Jun 12 12:15:34] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:34] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) <-- SIP read from 192.168.1.97:45864: [Jun 12 12:15:35] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- [Jun 12 12:15:37] DEBUG[27939]: chan_sip.c:1565 retrans_pkt: SIP TIMER: Rescheduling retransmission #18 (4) SIP/2.0 - 1 [Jun 12 12:15:37] DEBUG[27939]: chan_sip.c:1579 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #18)) Retransmitting #4 (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:41] DEBUG[27939]: chan_sip.c:1565 retrans_pkt: SIP TIMER: Rescheduling retransmission #18 (5) SIP/2.0 - 1 [Jun 12 12:15:41] DEBUG[27939]: chan_sip.c:1579 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #18)) Retransmitting #5 (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 (42) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK271a9442;rport (63) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "asterisk" ;tag=as65a57706 (59) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (32) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (36) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 (54) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Date: Mon, 12 Jun 2006 16:15:44 GMT (35) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: Supported: replaces (19) [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK271a9442;rport From: "asterisk" ;tag=as65a57706 To: Contact: Call-ID: 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:44 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:44] DEBUG[27939]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #22 [Jun 12 12:15:45] DEBUG[27939]: chan_sip.c:1565 retrans_pkt: SIP TIMER: Rescheduling retransmission #18 (6) SIP/2.0 - 1 [Jun 12 12:15:45] DEBUG[27939]: chan_sip.c:1579 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #18)) Retransmitting #6 (no NAT) to 192.168.1.97:45864: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.97:45864;rport;branch=z9hG4bK825495BD7F144811A1E872501A252B90;received=192.168.1.97 From: 151 ;tag=194809670 To: ;tag=as3cddfce0 Call-ID: 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 CSeq: 26483 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 277 v=0 o=root 27932 27933 IN IP4 192.168.1.92 s=session c=IN IP4 192.168.1.92 t=0 0 m=audio 12992 RTP/AVP 3 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Jun 12 12:15:45] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #22:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK271a9442;rport From: "asterisk" ;tag=as65a57706 To: Contact: Call-ID: 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:44 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- <-- SIP read from 192.168.1.97:45864: [Jun 12 12:15:46] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- [Jun 12 12:15:46] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #22:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK271a9442;rport From: "asterisk" ;tag=as65a57706 To: Contact: Call-ID: 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:44 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:47] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #22:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK271a9442;rport From: "asterisk" ;tag=as65a57706 To: Contact: Call-ID: 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:44 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:48] DEBUG[27939]: chan_sip.c:1560 retrans_pkt: SIP TIMER: Not rescheduling id #22:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (no NAT) to 192.168.1.97:45864: OPTIONS sip:151@192.168.1.97:45864 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK271a9442;rport From: "asterisk" ;tag=as65a57706 To: Contact: Call-ID: 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:44 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:48] DEBUG[27939]: chan_sip.c:2701 sip_destroy: Destroying SIP dialog 4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92 Really destroying SIP dialog '4e2298fd5809cd9157f0ab32244e58c4@192.168.1.92' Method: OPTIONS [Jun 12 12:15:48] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:48] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) [Jun 12 12:15:49] WARNING[27939]: chan_sip.c:1598 retrans_pkt: Maximum retries exceeded on transmission 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 for seqno 26483 (Critical Response) [Jun 12 12:15:49] WARNING[27939]: chan_sip.c:1615 retrans_pkt: Hanging up call 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97 - no reply to our critical packet. [Jun 12 12:15:49] DEBUG[27954]: channel.c:3380 ast_generic_bridge: Didn't get a frame from channel: SIP/151-61b0 [Jun 12 12:15:49] DEBUG[27954]: channel.c:3666 ast_channel_bridge: Bridge stops bridging channels SIP/151-61b0 and SIP/108-1b73 [Jun 12 12:15:49] DEBUG[27954]: channel.c:1479 ast_hangup: Hanging up channel 'SIP/108-1b73' [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:2894 sip_hangup: Hangup call SIP/108-1b73, SIP callid 15180d7b10f9a8db409fff092b76491b@192.168.1.92) [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:2902 sip_hangup: update_call_counter(108) - decrement call limit counter on hangup [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:2595 update_call_counter: Updating call counter for outgoing call [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:4818 reqprep: Strict routing enforced for session 15180d7b10f9a8db409fff092b76491b@192.168.1.92 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.108, port 5060 Reliably Transmitting (no NAT) to 192.168.1.108:5060: BYE sip:108@192.168.1.108:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK14a5dc85;rport From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: ;tag=001201b3355000495e771a50-746b4f85 Contact: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #25 [Jun 12 12:15:49] DEBUG[27954]: rtp.c:1308 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jun 12 12:15:49] DEBUG[27954]: app_dial.c:1615 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jun 12 12:15:49] DEBUG[27954]: app_macro.c:221 macro_exec: Spawn extension (macro-stdexten,s,2) exited non-zero on 'SIP/151-61b0' in macro 'stdexten' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:2258 __ast_pbx_run: Spawn extension (macro-stdexten,s,2) exited non-zero on 'SIP/151-61b0' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1675 pbx_extension_helper: Launching 'Hangup' -- Executing [h@macro-stdexten:1] Hangup("SIP/151-61b0", "") in new stack [Jun 12 12:15:49] DEBUG[27954]: pbx.c:2378 __ast_pbx_run: Spawn extension (macro-stdexten,h,1) exited non-zero on 'SIP/151-61b0' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '"Serge Vecher (videophone)" <151>' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '151' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '108' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'ldaccess' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'SIP/151-61b0' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'SIP/108-1b73' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-06-12 12:15:25' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-06-12 12:15:29' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-06-12 12:15:49' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '24' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '20' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1150128925.0' [Jun 12 12:15:49] DEBUG[27954]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Jun 12 12:15:49] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 108 [Jun 12 12:15:49] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/108 - state 1 (Not in use) <-- SIP read from 192.168.1.108:52025: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK14a5dc85;rport;received=192.168.1.90 From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 To: ;tag=001201b3355000495e771a50-746b4f85 Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Date: Mon, 12 Jun 2006 16:15:49 GMT CSeq: 103 BYE Server: CSCO/7 Content-Length: 0 [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: SIP/2.0 200 OK (14) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK14a5dc85;rport;received=192.168.1.90 (85) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "Serge Vecher (videophone)" ;tag=as7ad6dd32 (71) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: ;tag=001201b3355000495e771a50-746b4f85 (70) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Call-ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 (54) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Date: Mon, 12 Jun 2006 16:15:49 GMT (35) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 103 BYE (13) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Server: CSCO/7 (14) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Content-Length: 0 (17) [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 15180d7b10f9a8db409fff092b76491b@192.168.1.92 Their Tag 001201b3355000495e771a50-746b4f85 Our tag: as7ad6dd32 [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:1761 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #25 [Jun 12 12:15:49] DEBUG[27939]: chan_sip.c:1771 __sip_ack: Stopping retransmission on '15180d7b10f9a8db409fff092b76491b@192.168.1.92' of Request 103: Match Not Found Really destroying SIP dialog '15180d7b10f9a8db409fff092b76491b@192.168.1.92' Method: INVITE [Jun 12 12:15:49] DEBUG[27954]: channel.c:1479 ast_hangup: Hanging up channel 'SIP/151-61b0' [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:2894 sip_hangup: Hangup call SIP/151-61b0, SIP callid 0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97) [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:2902 sip_hangup: update_call_counter(151) - decrement call limit counter on hangup [Jun 12 12:15:49] DEBUG[27954]: chan_sip.c:2595 update_call_counter: Updating call counter for incoming call [Jun 12 12:15:49] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:15:49] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) Really destroying SIP dialog '0C734795-836D-43B2-A84E-5145C20EA405@192.168.1.97' Method: INVITE [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: OPTIONS sip:108@192.168.1.108:5060 SIP/2.0 (42) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK116c3be1;rport (63) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "asterisk" ;tag=as1bf8df58 (59) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: (32) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Contact: (36) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Call-ID: 57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92 (54) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Max-Forwards: 70 (16) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Date: Mon, 12 Jun 2006 16:15:53 GMT (35) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: Supported: replaces (19) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (no NAT) to 192.168.1.108:5060: OPTIONS sip:108@192.168.1.108:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK116c3be1;rport From: "asterisk" ;tag=as1bf8df58 To: Contact: Call-ID: 57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Jun 2006 16:15:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:1670 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #26 <-- SIP read from 192.168.1.108:52026: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK116c3be1;rport;received=192.168.1.90 From: "asterisk" ;tag=as1bf8df58 To: ;tag=001201b33550004a6406901c-1bc75cb2 Call-ID: 57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92 Date: Mon, 12 Jun 2006 16:15:53 GMT CSeq: 102 OPTIONS Server: CSCO/7 Content-Type: application/sdp Content-Length: 247 Allow: OPTIONS,INVITE,BYE,CANCEL,REGISTER,ACK,NOTIFY,REFER v=0 o=Cisco-SIPUA (null) (null) IN IP4 192.168.1.108 s=SIP Call c=IN IP4 192.168.1.108 t=0 0 m=audio 1 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 0: SIP/2.0 200 OK (14) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.92:5060;branch=z9hG4bK116c3be1;rport;received=192.168.1.90 (85) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 2: From: "asterisk" ;tag=as1bf8df58 (59) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 3: To: ;tag=001201b33550004a6406901c-1bc75cb2 (70) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 4: Call-ID: 57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92 (54) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 5: Date: Mon, 12 Jun 2006 16:15:53 GMT (35) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 7: Server: CSCO/7 (14) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 8: Content-Type: application/sdp (29) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 9: Content-Length: 247 (19) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 10: Allow: OPTIONS,INVITE,BYE,CANCEL,REGISTER,ACK,NOTIFY,REFER (58) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3971 parse_request: Header 11: (0) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: v=0 (3) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: o=Cisco-SIPUA (null) (null) IN IP4 192.168.1.108 (48) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: s=SIP Call (10) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: c=IN IP4 192.168.1.108 (22) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: t=0 0 (5) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: m=audio 1 RTP/AVP 0 8 18 101 (28) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:4003 parse_request: Line: a=fmtp:101 0-15 (15) --- (11 headers 11 lines)--- [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:3799 find_call: = Found Their Call ID: 57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92 Their Tag Our tag: as1bf8df58 [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:1761 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #26 [Jun 12 12:15:53] DEBUG[27939]: chan_sip.c:1771 __sip_ack: Stopping retransmission on '57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92' of Request 102: Match Not Found Really destroying SIP dialog '57b4cd883cb92a5b7a157d0a0afdbabb@192.168.1.92' Method: OPTIONS sip no debug SIP Debugging Disabled *CLI> [Jun 12 12:15:58] DEBUG[27939]: chan_sip.c:3751 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) stop grac[Jun 12 12:16:02] DEBUG[27939]: chan_sip.c:2701 sip_destroy: Destroying SIP dialog 57440f06301afaa62af1d7d84f0648bd@192.168.1.92 Really destroying SIP dialog '57440f06301afaa62af1d7d84f0648bd@192.168.1.92' Method: OPTIONS [Jun 12 12:16:02] DEBUG[27936]: chan_sip.c:13619 sip_devicestate: Checking device state for peer 151 [Jun 12 12:16:02] DEBUG[27936]: devicestate.c:189 do_state_change: Changing state for SIP/151 - state 1 (Not in use) efully Waiting for inactivity to perform halt... Executing last minute cleanups == Destroying musiconhold processes Asterisk cleanly ending (0). [root@kb-serge-laptop asterisk]#