core set debug [Apr 5 18:20:59] DEBUG[27260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/3013 [Apr 5 18:20:59] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 3013 [Apr 5 18:20:59] DEBUG[27253]: chan_iax2.c:9636 iax2_devicestate: Checking device state for device 3013 [Apr 5 18:20:59] DEBUG[27253]: chan_iax2.c:9644 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 3013? addr=456502361, defaddr=0 maxms=2000, lastms=68 [Apr 5 18:20:59] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for IAX2/3013 - state 1 (Not in use) [Apr 5 18:20:59] DEBUG[27288]: app_queue.c:546 changethread: Device 'IAX2/3013' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. 4 Core debug was 5 and is now 4 *CLI> core set verbose[Apr 5 18:21:03] DEBUG[27272]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) 4 Verbosity was 5 and is now 4 *CLI> sip [Apr 5 18:21:07] DEBUG[27272]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 1ee9bfd362e40cd4197666767c23def1@213.157.246.28 [Apr 5 18:21:07] Really destroying SIP dialog '1ee9bfd362e40cd4197666767c23def1@213.157.246.28' Method: OPTIONS [Apr 5 18:21:07] DEBUG[27272]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1001 [Apr 5 18:21:07] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1001 [Apr 5 18:21:07] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1001 [Apr 5 18:21:07] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1001 - state 1 (Not in use) [Apr 5 18:21:07] DEBUG[27290]: app_queue.c:546 changethread: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. set debugf No such command 'sip set debugf' (type 'help' for help) *CLI> sip set debugf SIP Debugging enabled *CLI> [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 (56) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK58643a35;rport (65) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as63f84487 (61) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Contact: (38) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 (56) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 16:21:17 GMT (35) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Apr 5 18:21:17] Reliably Transmitting (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK58643a35;rport From: "asterisk" ;tag=as63f84487 To: Contact: Call-ID: 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:17 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:17] DEBUG[27272]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #48 [Apr 5 18:21:18] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #48:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:18] Retransmitting #1 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK58643a35;rport From: "asterisk" ;tag=as63f84487 To: Contact: Call-ID: 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:17 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #48:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:19] Retransmitting #2 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK58643a35;rport From: "asterisk" ;tag=as63f84487 To: Contact: Call-ID: 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:17 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:19] <--- SIP read from 81.170.212.11:5068 ---> INVITE sip:55@voip.tele.si SIP/2.0 Date: Thu, 05 Apr 2007 16:21:25 GMT CSeq: 1 INVITE Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKce48b75e-ffe1-db11-857e-0004234d971b;rport User-Agent: Ekiga/2.1.0 From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap To: Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING Content-Type: application/sdp Content-Length: 238 Max-Forwards: 70 v=0 o=- 1175790085 1175790085 IN IP4 192.168.1.10 s=Opal SIP Session c=IN IP4 192.168.1.10 t=0 0 m=audio 5010 RTP/AVP 112 101 a=rtpmap:112 Speex/8000 a=fmtp:112 sr=8000,mode=any a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:55@voip.tele.si SIP/2.0 (34) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Date: Thu, 05 Apr 2007 16:21:25 GMT (35) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: CSeq: 1 INVITE (14) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKce48b75e-ffe1-db11-857e-0004234d971b;rport (91) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: User-Agent: Ekiga/2.1.0 (23) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b (86) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap (49) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: To: (25) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Contact: (51) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING (67) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Content-Type: application/sdp (29) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: Content-Length: 238 (19) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 12: Max-Forwards: 70 (16) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 13: (0) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: o=- 1175790085 1175790085 IN IP4 192.168.1.10 (45) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: s=Opal SIP Session (18) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.1.10 (21) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: m=audio 5010 RTP/AVP 112 101 (28) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=rtpmap:112 Speex/8000 (23) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=fmtp:112 sr=8000,mode=any (27) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 5 18:21:19] --- (13 headers 10 lines) --- [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2580 do_setnat: Setting NAT on VRTP to On [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to On [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for 36269f5e-ffe1-db11-857e-0004234d971b@lap - INVITE (With RTP) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 5 18:21:19] Sending to 81.170.212.11 : 5068 (NAT) [Apr 5 18:21:19] Using INVITE request as basis request - 36269f5e-ffe1-db11-857e-0004234d971b@lap [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2580 do_setnat: Setting NAT on VRTP to On [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to On [Apr 5 18:21:19] <--- Reliably Transmitting (NAT) to 81.170.212.11:5068 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKce48b75e-ffe1-db11-857e-0004234d971b;received=81.170.212.11;rport=5068 From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b To: ;tag=as1a48103b Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="32b8b930" Content-Length: 0 <------------> [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #50 [Apr 5 18:21:19] Scheduling destruction of SIP dialog '36269f5e-ffe1-db11-857e-0004234d971b@lap' in 32000 ms (Method: INVITE) [Apr 5 18:21:19] Found user '1001' [Apr 5 18:21:19] <--- SIP read from 81.170.212.11:5068 ---> ACK sip:55@voip.tele.si SIP/2.0 CSeq: 1 ACK Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKce48b75e-ffe1-db11-857e-0004234d971b;rport From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap To: ;tag=as1a48103b Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING Content-Length: 0 Max-Forwards: 70 <-------------> [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: ACK sip:55@voip.tele.si SIP/2.0 (31) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: CSeq: 1 ACK (11) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKce48b75e-ffe1-db11-857e-0004234d971b;rport (91) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b (86) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap (49) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: To: ;tag=as1a48103b (40) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING (67) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: Content-Length: 0 (17) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: (0) [Apr 5 18:21:19] --- (9 headers 0 lines) --- [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #50 [Apr 5 18:21:19] DEBUG[27272]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '36269f5e-ffe1-db11-857e-0004234d971b@lap' of Response 1: Match Not Found [Apr 5 18:21:20] <--- SIP read from 81.170.212.11:5068 ---> INVITE sip:55@voip.tele.si SIP/2.0 Date: Thu, 05 Apr 2007 16:21:26 GMT CSeq: 2 INVITE Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKb047cc5e-ffe1-db11-857e-0004234d971b;rport User-Agent: Ekiga/2.1.0 From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap To: Contact: Proxy-Authorization: Digest username="1001", realm="asterisk", nonce="32b8b930", uri="sip:55@voip.tele.si", algorithm=md5, response="30413b2d492395d73f200eeead7112af" Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING Content-Type: application/sdp Content-Length: 238 Max-Forwards: 70 v=0 o=- 1175790086 1175790086 IN IP4 192.168.1.10 s=Opal SIP Session c=IN IP4 192.168.1.10 t=0 0 m=audio 5010 RTP/AVP 112 101 a=rtpmap:112 Speex/8000 a=fmtp:112 sr=8000,mode=any a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:55@voip.tele.si SIP/2.0 (34) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Date: Thu, 05 Apr 2007 16:21:26 GMT (35) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: CSeq: 2 INVITE (14) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKb047cc5e-ffe1-db11-857e-0004234d971b;rport (91) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: User-Agent: Ekiga/2.1.0 (23) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b (86) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap (49) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: To: (25) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Contact: (51) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Proxy-Authorization: Digest username="1001", realm="asterisk", nonce="32b8b930", uri="sip:55@voip.tele.si", algorithm=md5, response="30413b2d492395d73f200eeead7112af" (166) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING (67) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: Content-Type: application/sdp (29) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 238 (19) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 13: Max-Forwards: 70 (16) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 14: (0) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: o=- 1175790086 1175790086 IN IP4 192.168.1.10 (45) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: s=Opal SIP Session (18) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.1.10 (21) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: m=audio 5010 RTP/AVP 112 101 (28) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=rtpmap:112 Speex/8000 (23) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=fmtp:112 sr=8000,mode=any (27) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 5 18:21:20] --- (14 headers 10 lines) --- [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 5 18:21:20] Sending to 81.170.212.11 : 5068 (NAT) [Apr 5 18:21:20] Using INVITE request as basis request - 36269f5e-ffe1-db11-857e-0004234d971b@lap [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:2580 do_setnat: Setting NAT on VRTP to On [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to On [Apr 5 18:21:20] Found user '1001' [Apr 5 18:21:20] Found RTP audio format 112 [Apr 5 18:21:20] Found RTP audio format 101 [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4899 process_sdp: Peer doesn't provide T.38 UDPTL [Apr 5 18:21:20] Peer audio RTP is at port 192.168.1.10:5010 [Apr 5 18:21:20] Found description format Speex for ID 112 [Apr 5 18:21:20] Got unsupported a:fmtp in SDP offer [Apr 5 18:21:20] Found description format telephone-event for ID 101 [Apr 5 18:21:20] Got unsupported a:fmtp in SDP offer [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel [Apr 5 18:21:20] Capabilities: us - 0x30a (gsm|alaw|g729|speex), peer - audio=0x200 (speex)/video=0x0 (nothing), combined - 0x200 (speex) [Apr 5 18:21:20] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 5 18:21:20] Peer audio RTP is at port 192.168.1.10:5010 [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x200 (speex) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:13401 handle_request_invite: Checking SIP call limits for device 1001 [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Apr 5 18:21:20] Looking for 55 in main (domain voip.tele.si) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3805 sip_new: *** Our native formats are 0x200 (speex) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x200 (speex) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x30a (gsm|alaw|g729|speex) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x200 (speex) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:7980 build_route: build_route: Contact hop: [Apr 5 18:21:20] list_route: hop: [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:13476 handle_request_invite: SIP/1001-097563e0: New call is still down.... Trying... [Apr 5 18:21:20] <--- Transmitting (NAT) to 81.170.212.11:5068 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKb047cc5e-ffe1-db11-857e-0004234d971b;received=81.170.212.11;rport=5068 From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b To: Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 18:21:20] DEBUG[27272]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1001-097563e0 [Apr 5 18:21:20] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1001 [Apr 5 18:21:20] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1001 [Apr 5 18:21:20] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1001 - state 1 (Not in use) [Apr 5 18:21:20] DEBUG[27293]: pbx.c:1795 pbx_extension_helper: Launching 'Answer' [Apr 5 18:21:20] -- Executing [55@main:1] Answer("SIP/1001-097563e0", "") in new stack [Apr 5 18:21:20] DEBUG[27293]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1001-097563e0 [Apr 5 18:21:20] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1001 [Apr 5 18:21:20] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1001 [Apr 5 18:21:20] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1001 - state 1 (Not in use) [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:3463 sip_answer: SIP answering channel: SIP/1001-097563e0 [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:6188 add_sdp: ** Our capability: 0x200 (speex) Video flag: True [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 5 18:21:20] Audio is at 213.157.246.28 port 7092 [Apr 5 18:21:20] Adding codec 0x200 (speex) to SDP [Apr 5 18:21:20] Adding non-codec 0x1 (telephone-event) to SDP [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x200 (speex) [Apr 5 18:21:20] <--- Reliably Transmitting (NAT) to 81.170.212.11:5068 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKb047cc5e-ffe1-db11-857e-0004234d971b;received=81.170.212.11;rport=5068 From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b To: ;tag=as29545f9d Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 248 v=0 o=root 27249 27249 IN IP4 213.157.246.28 s=session c=IN IP4 213.157.246.28 t=0 0 m=audio 7092 RTP/AVP 112 101 a=rtpmap:112 speex/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 5 18:21:20] DEBUG[27293]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #52 [Apr 5 18:21:20] DEBUG[27293]: pbx.c:1795 pbx_extension_helper: Launching 'Wait' [Apr 5 18:21:20] -- Executing [55@main:2] Wait("SIP/1001-097563e0", "2") in new stack [Apr 5 18:21:20] DEBUG[27294]: app_queue.c:546 changethread: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:20] DEBUG[27295]: app_queue.c:546 changethread: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:20] <--- SIP read from 81.170.212.11:5068 ---> ACK sip:55@213.157.246.28 SIP/2.0 CSeq: 2 ACK Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bK324be75e-ffe1-db11-857e-0004234d971b;rport From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap To: ;tag=as29545f9d Contact: Proxy-Authorization: Digest username="1001", realm="asterisk", nonce="32b8b930", uri="sip:55@213.157.246.28", algorithm=md5, response="f50417112cea873c1f686e695dfbe360" Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING Content-Length: 0 Max-Forwards: 70 <-------------> [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: ACK sip:55@213.157.246.28 SIP/2.0 (33) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: CSeq: 2 ACK (11) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bK324be75e-ffe1-db11-857e-0004234d971b;rport (91) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b (86) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap (49) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: To: ;tag=as29545f9d (40) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Contact: (51) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: Proxy-Authorization: Digest username="1001", realm="asterisk", nonce="32b8b930", uri="sip:55@213.157.246.28", algorithm=md5, response="f50417112cea873c1f686e695dfbe360" (168) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING (67) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Max-Forwards: 70 (16) [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 18:21:20] --- (11 headers 0 lines) --- [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #52 [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '36269f5e-ffe1-db11-857e-0004234d971b@lap' of Response 2: Match Not Found [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #48:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:20] Retransmitting #3 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK58643a35;rport From: "asterisk" ;tag=as63f84487 To: Contact: Call-ID: 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:17 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:20] DEBUG[27293]: rtp.c:1151 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 81.170.212.11:5010 [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '69954f3c067eb79508ff9b9652dd0476@213.157.246.28' [Apr 5 18:21:20] DEBUG[27272]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 69954f3c067eb79508ff9b9652dd0476@213.157.246.28 [Apr 5 18:21:20] Really destroying SIP dialog '69954f3c067eb79508ff9b9652dd0476@213.157.246.28' Method: REGISTER [Apr 5 18:21:21] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #48:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:21] Retransmitting #4 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK58643a35;rport From: "asterisk" ;tag=as63f84487 To: Contact: Call-ID: 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:17 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:21] DEBUG[27272]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28 [Apr 5 18:21:21] Really destroying SIP dialog '24f7c48a43348bbf7916219c7d83c7cc@213.157.246.28' Method: OPTIONS [Apr 5 18:21:21] DEBUG[27272]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1001 [Apr 5 18:21:21] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1001 [Apr 5 18:21:21] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1001 [Apr 5 18:21:21] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1001 - state 1 (Not in use) [Apr 5 18:21:21] DEBUG[27296]: app_queue.c:546 changethread: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:22] DEBUG[27293]: pbx.c:1795 pbx_extension_helper: Launching 'MusicOnHold' [Apr 5 18:21:22] -- Executing [55@main:3] MusicOnHold("SIP/1001-097563e0", "") in new stack [Apr 5 18:21:22] -- Started music on hold, class 'default', on SIP/1001-097563e0 [Apr 5 18:21:22] DEBUG[27293]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 5 18:21:22] DEBUG[27293]: channel.c:2332 __ast_read: Generator got voice, switching to phase locked mode [Apr 5 18:21:22] DEBUG[27293]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 5 18:21:22] DEBUG[27293]: channel.c:2845 set_format: Set channel SIP/1001-097563e0 to write format slin [Apr 5 18:21:22] DEBUG[27293]: res_musiconhold.c:254 ast_moh_files_next: SIP/1001-097563e0 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix' [Apr 5 18:21:22] DEBUG[27293]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to speex [Apr 5 18:21:22] DEBUG[27293]: rtp.c:2706 ast_rtp_write: Created smoother: format: 512 ms: 20 len: 20 [Apr 5 18:21:24] DEBUG[27272]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '1974112122-841012261@192.168.2.10' [Apr 5 18:21:24] DEBUG[27272]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 1974112122-841012261@192.168.2.10 [Apr 5 18:21:24] Really destroying SIP dialog '1974112122-841012261@192.168.2.10' Method: REGISTER [Apr 5 18:21:24] DEBUG[27272]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '2bef617f3b330ac2661f972f7fe14fe6@192.168.1.51' [Apr 5 18:21:24] DEBUG[27272]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 2bef617f3b330ac2661f972f7fe14fe6@192.168.1.51 [Apr 5 18:21:24] Really destroying SIP dialog '2bef617f3b330ac2661f972f7fe14fe6@192.168.1.51' Method: OPTIONS [Apr 5 18:21:27] <--- SIP read from 86.61.13.5:5060 ---> REGISTER sip:213.157.246.28 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.10:5060;rport;branch=z9hG4bK26031 From: 1005 ;tag=221173498 To: 1005 Call-ID: 1974112122-841012261@192.168.2.10 CSeq: 113 REGISTER Contact: expires: 60 user-agent: Voip Phone 1.0 Content-Length: 0 <-------------> [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:213.157.246.28 SIP/2.0 (35) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.10:5060;rport;branch=z9hG4bK26031 (60) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: From: 1005 ;tag=221173498 (50) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: To: 1005 (34) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 1974112122-841012261@192.168.2.10 (42) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: CSeq: 113 REGISTER (18) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Contact: (37) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: expires: 60 (11) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: user-agent: Voip Phone 1.0 (26) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: (0) [Apr 5 18:21:27] --- (10 headers 0 lines) --- [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for 1974112122-841012261@192.168.2.10 - REGISTER (No RTP) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 5 18:21:27] Using latest REGISTER request as basis request [Apr 5 18:21:27] Sending to 86.61.13.5 : 5060 (NAT) [Apr 5 18:21:27] <--- Transmitting (NAT) to 86.61.13.5:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.10:5060;branch=z9hG4bK26031;received=86.61.13.5;rport=5060 From: 1005 ;tag=221173498 To: 1005 Call-ID: 1974112122-841012261@192.168.2.10 CSeq: 113 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 18:21:27] <--- Transmitting (NAT) to 86.61.13.5:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.2.10:5060;branch=z9hG4bK26031;received=86.61.13.5;rport=5060 From: 1005 ;tag=221173498 To: 1005 ;tag=as501ea50c Call-ID: 1974112122-841012261@192.168.2.10 CSeq: 113 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1cc2fa5b" Content-Length: 0 <------------> [Apr 5 18:21:27] Scheduling destruction of SIP dialog '1974112122-841012261@192.168.2.10' in 32000 ms (Method: REGISTER) [Apr 5 18:21:27] <--- SIP read from 86.61.13.5:5060 ---> REGISTER sip:213.157.246.28 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.10:5060;rport;branch=z9hG4bK10303 From: 1005 ;tag=221173498 To: 1005 Call-ID: 1974112122-841012261@192.168.2.10 CSeq: 114 REGISTER Contact: Authorization: Digest username="1005", realm="asterisk", nonce="1cc2fa5b", uri="sip:213.157.246.28", response="9d2f3e0237a0ffcbceb6a7c6871946df", algorithm=MD5 expires: 60 user-agent: Voip Phone 1.0 Content-Length: 0 <-------------> [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:213.157.246.28 SIP/2.0 (35) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.10:5060;rport;branch=z9hG4bK10303 (60) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: From: 1005 ;tag=221173498 (50) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: To: 1005 (34) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 1974112122-841012261@192.168.2.10 (42) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: CSeq: 114 REGISTER (18) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Contact: (37) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: Authorization: Digest username="1005", realm="asterisk", nonce="1cc2fa5b", uri="sip:213.157.246.28", response="9d2f3e0237a0ffcbceb6a7c6871946df", algorithm=MD5 (159) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: expires: 60 (11) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: user-agent: Voip Phone 1.0 (26) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Content-Length: 0 (17) [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 18:21:27] --- (11 headers 0 lines) --- [Apr 5 18:21:27] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 5 18:21:27] Using latest REGISTER request as basis request [Apr 5 18:21:27] Sending to 86.61.13.5 : 5060 (NAT) [Apr 5 18:21:27] <--- Transmitting (NAT) to 86.61.13.5:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.10:5060;branch=z9hG4bK10303;received=86.61.13.5;rport=5060 From: 1005 ;tag=221173498 To: 1005 Call-ID: 1974112122-841012261@192.168.2.10 CSeq: 114 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 18:21:27] <--- Transmitting (NAT) to 86.61.13.5:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.10:5060;branch=z9hG4bK10303;received=86.61.13.5;rport=5060 From: 1005 ;tag=221173498 To: 1005 ;tag=as501ea50c Call-ID: 1974112122-841012261@192.168.2.10 CSeq: 114 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Thu, 05 Apr 2007 16:21:27 GMT Content-Length: 0 <------------> [Apr 5 18:21:27] DEBUG[27272]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1005 [Apr 5 18:21:27] Scheduling destruction of SIP dialog '1974112122-841012261@192.168.2.10' in 32000 ms (Method: REGISTER) [Apr 5 18:21:27] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1005 [Apr 5 18:21:27] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1005 [Apr 5 18:21:27] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1005 - state 1 (Not in use) [Apr 5 18:21:27] DEBUG[27298]: app_queue.c:546 changethread: Device 'SIP/1005' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 (56) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK27032148;rport (65) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as256faf19 (61) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Contact: (38) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 (56) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 16:21:31 GMT (35) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Apr 5 18:21:31] Reliably Transmitting (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK27032148;rport From: "asterisk" ;tag=as256faf19 To: Contact: Call-ID: 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:31] DEBUG[27272]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #58 [Apr 5 18:21:31] DEBUG[27293]: rtp.c:873 ast_rtcp_read: Got RTCP report of 84 bytes [Apr 5 18:21:32] <--- SIP read from 81.170.212.11:5068 ---> BYE sip:55@213.157.246.28 SIP/2.0 CSeq: 4 BYE Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKc61f2266-ffe1-db11-857e-0004234d971b;rport From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap To: ;tag=as29545f9d Contact: Proxy-Authorization: Digest username="1001", realm="asterisk", nonce="32b8b930", uri="sip:55@213.157.246.28", algorithm=md5, response="a3b1bf6462fbf14c51598238865606a3" Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING Content-Length: 0 Max-Forwards: 70 <-------------> [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: BYE sip:55@213.157.246.28 SIP/2.0 (33) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: CSeq: 4 BYE (11) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKc61f2266-ffe1-db11-857e-0004234d971b;rport (91) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b (86) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap (49) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: To: ;tag=as29545f9d (40) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Contact: (51) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: Proxy-Authorization: Digest username="1001", realm="asterisk", nonce="32b8b930", uri="sip:55@213.157.246.28", algorithm=md5, response="a3b1bf6462fbf14c51598238865606a3" (168) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE,INFO,PING (67) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Max-Forwards: 70 (16) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 18:21:32] --- (11 headers 0 lines) --- [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 5 18:21:32] Sending to 81.170.212.11 : 5068 (NAT) [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 36269f5e-ffe1-db11-857e-0004234d971b@lap [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:14190 handle_request_bye: Received bye, issuing owner hangup [Apr 5 18:21:32] <--- Transmitting (NAT) to 81.170.212.11:5068 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.10:5068;branch=z9hG4bKc61f2266-ffe1-db11-857e-0004234d971b;received=81.170.212.11;rport=5068 From: "Jure Petrovic" ;tag=32349f5e-ffe1-db11-857e-0004234d971b To: ;tag=as29545f9d Call-ID: 36269f5e-ffe1-db11-857e-0004234d971b@lap CSeq: 4 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 18:21:32] -- Stopped music on hold on SIP/1001-097563e0 [Apr 5 18:21:32] DEBUG[27293]: channel.c:2845 set_format: Set channel SIP/1001-097563e0 to write format speex [Apr 5 18:21:32] DEBUG[27293]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 5 18:21:32] DEBUG[27293]: pbx.c:2393 __ast_pbx_run: Spawn extension (main,55,3) exited non-zero on 'SIP/1001-097563e0' [Apr 5 18:21:32] == Spawn extension (main, 55, 3) exited non-zero on 'SIP/1001-097563e0' [Apr 5 18:21:32] DEBUG[27293]: cdr_pgsql.c:124 pgsql_log: cdr_pgsql: inserting a CDR record. [Apr 5 18:21:32] DEBUG[27293]: cdr_pgsql.c:133 pgsql_log: 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 ('2007-04-05 18:21:20','"Jure 1001" <1001>','1001','55','main', 'SIP/1001-097563e0','','MusicOnHold','',12,12,'ANSWERED',3,'JURE','1175790080.0','') [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Jure 1001" <1001>' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1001' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '55' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'main' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/1001-097563e0' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'MusicOnHold' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 18:21:20' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 18:21:20' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 18:21:32' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'JURE' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175790080.0' [Apr 5 18:21:32] DEBUG[27293]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 18:21:32] DEBUG[27293]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/1001-097563e0' [Apr 5 18:21:32] DEBUG[27293]: chan_sip.c:3312 sip_hangup: Hangup call SIP/1001-097563e0, SIP callid 36269f5e-ffe1-db11-857e-0004234d971b@lap) [Apr 5 18:21:32] DEBUG[27293]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1001-097563e0 [Apr 5 18:21:32] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1001 [Apr 5 18:21:32] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1001 [Apr 5 18:21:32] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1001 - state 1 (Not in use) [Apr 5 18:21:32] DEBUG[27300]: app_queue.c:546 changethread: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:32] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #58:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:32] Retransmitting #1 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK27032148;rport From: "asterisk" ;tag=as256faf19 To: Contact: Call-ID: 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:32] Really destroying SIP dialog '36269f5e-ffe1-db11-857e-0004234d971b@lap' Method: BYE [Apr 5 18:21:33] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #58:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:33] Retransmitting #2 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK27032148;rport From: "asterisk" ;tag=as256faf19 To: Contact: Call-ID: 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:34] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #58:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:34] Retransmitting #3 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK27032148;rport From: "asterisk" ;tag=as256faf19 To: Contact: Call-ID: 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:1861 retrans_pkt: SIP TIMER: Not rescheduling id #58:OPTIONS (Method 3) (No timer T1) [Apr 5 18:21:35] Retransmitting #4 (NAT) to 81.170.212.11:5061: OPTIONS sip:1001@192.168.1.10:5061;transport=udp SIP/2.0 Via: SIP/2.0/UDP 213.157.246.28:5060;branch=z9hG4bK27032148;rport From: "asterisk" ;tag=as256faf19 To: Contact: Call-ID: 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 16:21:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28 [Apr 5 18:21:35] Really destroying SIP dialog '49bd46ca1d9e49a976d4680b2d67928c@213.157.246.28' Method: OPTIONS [Apr 5 18:21:35] DEBUG[27272]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1001 [Apr 5 18:21:35] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1001 [Apr 5 18:21:35] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1001 [Apr 5 18:21:35] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1001 - state 1 (Not in use) [Apr 5 18:21:35] DEBUG[27301]: app_queue.c:546 changethread: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:35] <--- SIP read from 86.61.76.107:5061 ---> REGISTER sip:voip.tele.si SIP/2.0 Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKglF7NaFqPEgaQD9k;rport Max-Forwards: 70 User-Agent: IP PHONE 3 V1.52.007 CFG0 From: "1010" ;tag=yVGUjBEsB5wWmpPm To: "1010" Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 CSeq: 7018 REGISTER Contact: Expires: 60 Content-Length: 0 <-------------> [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:voip.tele.si SIP/2.0 (33) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKglF7NaFqPEgaQD9k;rport (71) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: User-Agent: IP PHONE 3 V1.52.007 CFG0 (41) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: From: "1010" ;tag=yVGUjBEsB5wWmpPm (57) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: To: "1010" (34) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 (39) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: CSeq: 7018 REGISTER (19) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Contact: (37) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Expires: 60 (11) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Content-Length: 0 (17) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 18:21:35] --- (11 headers 0 lines) --- [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for FXRoMIbTSKxP60GG@192.168.1.112 - REGISTER (No RTP) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 5 18:21:35] Using latest REGISTER request as basis request [Apr 5 18:21:35] Sending to 86.61.76.107 : 5061 (NAT) [Apr 5 18:21:35] <--- Transmitting (NAT) to 86.61.76.107:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKglF7NaFqPEgaQD9k;received=86.61.76.107;rport=5061 From: "1010" ;tag=yVGUjBEsB5wWmpPm To: "1010" Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 CSeq: 7018 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 18:21:35] <--- Transmitting (NAT) to 86.61.76.107:5061 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKglF7NaFqPEgaQD9k;received=86.61.76.107;rport=5061 From: "1010" ;tag=yVGUjBEsB5wWmpPm To: "1010" ;tag=as1cd2d9d2 Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 CSeq: 7018 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="01a93908" Content-Length: 0 <------------> [Apr 5 18:21:35] Scheduling destruction of SIP dialog 'FXRoMIbTSKxP60GG@192.168.1.112' in 32000 ms (Method: REGISTER) [Apr 5 18:21:35] DEBUG[27263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/3011 [Apr 5 18:21:35] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 3011 [Apr 5 18:21:35] DEBUG[27253]: chan_iax2.c:9636 iax2_devicestate: Checking device state for device 3011 [Apr 5 18:21:35] DEBUG[27253]: chan_iax2.c:9644 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 3011? addr=-2093462079, defaddr=0 maxms=2000, lastms=61 [Apr 5 18:21:35] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for IAX2/3011 - state 1 (Not in use) [Apr 5 18:21:35] DEBUG[27302]: app_queue.c:546 changethread: Device 'IAX2/3011' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 18:21:35] <--- SIP read from 86.61.76.107:5061 ---> REGISTER sip:voip.tele.si SIP/2.0 Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKBPNQOJ5u8XZiumGw;rport Max-Forwards: 70 User-Agent: IP PHONE 3 V1.52.007 CFG0 From: "1010" ;tag=yVGUjBEsB5wWmpPm To: "1010" Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 CSeq: 7019 REGISTER Contact: Expires: 60 Authorization: Digest username="1010", realm="asterisk", nonce="01a93908", uri="sip:voip.tele.si", response="daf647ddd1b6f94ea62e9c2575ece436", algorithm=MD5 Content-Length: 0 <-------------> [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:voip.tele.si SIP/2.0 (33) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKBPNQOJ5u8XZiumGw;rport (71) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 3: User-Agent: IP PHONE 3 V1.52.007 CFG0 (41) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 4: From: "1010" ;tag=yVGUjBEsB5wWmpPm (57) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 5: To: "1010" (34) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 6: Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 (39) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 7: CSeq: 7019 REGISTER (19) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 8: Contact: (37) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 9: Expires: 60 (11) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 10: Authorization: Digest username="1010", realm="asterisk", nonce="01a93908", uri="sip:voip.tele.si", response="daf647ddd1b6f94ea62e9c2575ece436", algorithm=MD5 (157) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 11: Content-Length: 0 (17) [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:4573 parse_request: Header 12: (0) [Apr 5 18:21:35] --- (12 headers 0 lines) --- [Apr 5 18:21:35] DEBUG[27272]: chan_sip.c:14633 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 5 18:21:35] Using latest REGISTER request as basis request [Apr 5 18:21:35] Sending to 86.61.76.107 : 5061 (NAT) [Apr 5 18:21:35] <--- Transmitting (NAT) to 86.61.76.107:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKBPNQOJ5u8XZiumGw;received=86.61.76.107;rport=5061 From: "1010" ;tag=yVGUjBEsB5wWmpPm To: "1010" Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 CSeq: 7019 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 18:21:35] -- Saved useragent "IP PHONE 3 V1.52.007 CFG0 " for peer 1010 [Apr 5 18:21:35] <--- Transmitting (NAT) to 86.61.76.107:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 86.61.76.107:5061;branch=z9hG4bKBPNQOJ5u8XZiumGw;received=86.61.76.107;rport=5061 From: "1010" ;tag=yVGUjBEsB5wWmpPm To: "1010" ;tag=as1cd2d9d2 Call-ID: FXRoMIbTSKxP60GG@192.168.1.112 CSeq: 7019 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Thu, 05 Apr 2007 16:21:35 GMT Content-Length: 0 <------------> [Apr 5 18:21:35] DEBUG[27272]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1010 [Apr 5 18:21:35] DEBUG[27253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1010 [Apr 5 18:21:35] DEBUG[27253]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 1010 [Apr 5 18:21:35] DEBUG[27253]: devicestate.c:287 do_state_change: Changing state for SIP/1010 - state 1 (Not in use) [Apr 5 18:21:35] Scheduling destruction of SIP dialog 'FXRoMIbTSKxP60GG@192.168.1.112' in 32000 ms (Method: REGISTER) [Apr 5 18:21:35] DEBUG[27303]: app_queue.c:546 changethread: Device 'SIP/1010' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.