Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'marvin' (pid 10753)*CLI> core set debug 4 Core debug was 5 and is now 4 *CLI> core set verbose 4 Verbosity was 5 and is now 4 *CLI> sip set debug on SIP Debugging enabled *CLI> *CLI> *CLI> *CLI> <--- SIP read from 192.168.1.254:1111 ---> SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-uyivybelwvpl;rport From: ;tag=1na1y82fyn To: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 1 SUBSCRIBE Max-Forwards: 70 Contact: ;flow-id=1 Event: dialog;purpose=call-completion Accept: application/dialog-info+xml Expires: 3600 Content-Length: 0 <-------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 48]: SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-uyivybelwvpl;rport [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 42]: From: ;tag=1na1y82fyn [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 36]: To: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 17]: CSeq: 1 SUBSCRIBE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 37]: Event: dialog;purpose=call-completion [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 35]: Accept: application/dialog-info+xml [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 13]: Expires: 3600 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 17]: Content-Length: 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4369 sip_alloc: Allocating new SIP dialog for 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD - SUBSCRIBE (No RTP) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Creating new subscription [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14363 handle_request_subscribe: Initializing initreq for method SUBSCRIBE - callid 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD Sending to 192.168.1.254 : 1111 (NAT) Found peer '101' for '101' from 192.168.1.254:1111 <--- Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-uyivybelwvpl;received=192.168.1.254;rport=1111 From: ;tag=1na1y82fyn To: ;tag=as554c9d64 Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 1 SUBSCRIBE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="42a931d6" Content-Length: 0 <------------> Scheduling destruction of SIP dialog '3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD' in 32000 ms (Method: SUBSCRIBE) <--- SIP read from 192.168.1.254:1111 ---> INVITE sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-s53c4ufq5a2c;rport From: "Sebastian Roesner" ;tag=yl2pk9uifb To: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 1 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/6.5.2 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 473 v=0 o=root 96225157 96225157 IN IP4 192.168.1.254 s=call c=IN IP4 192.168.1.254 t=0 0 m=audio 49562 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ieJTxRsjwfyyXXzOkxqj2UOoVlaG9N7/9N6BwTU0 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 45]: INVITE sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-s53c4ufq5a2c;rport [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=yl2pk9uifb [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 36]: To: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 14]: CSeq: 1 INVITE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 41]: P-Key-Flags: resolution="31x13", keys="4" [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 25]: User-Agent: snom360/6.5.2 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 23]: Accept: application/sdp [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 13 [ 44]: Supported: timer, 100rel, replaces, callerid [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 14 [ 35]: Session-Expires: 3600;refresher=uas [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 15 [ 10]: Min-SE: 90 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 16 [ 29]: Content-Type: application/sdp [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 17 [ 19]: Content-Length: 473 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 18 [ 0]: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 0 [ 3]: v=0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 1 [ 45]: o=root 96225157 96225157 IN IP4 192.168.1.254 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 2 [ 6]: s=call [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.254 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 4 [ 5]: t=0 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 5 [ 40]: m=audio 49562 RTP/AVP 0 8 9 2 3 18 4 101 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 6 [ 82]: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ieJTxRsjwfyyXXzOkxqj2UOoVlaG9N7/9N6BwTU0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 7 [ 20]: a=rtpmap:0 pcmu/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 8 [ 20]: a=rtpmap:8 pcma/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 9 [ 20]: a=rtpmap:9 g722/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 10 [ 23]: a=rtpmap:2 g726-32/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 11 [ 19]: a=rtpmap:3 gsm/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 12 [ 21]: a=rtpmap:18 g729/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 13 [ 20]: a=rtpmap:4 g723/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 15 [ 15]: a=fmtp:101 0-16 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 16 [ 10]: a=ptime:20 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 17 [ 21]: a=encryption:optional [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 18 [ 10]: a=sendrecv --- (18 headers 19 lines) --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2670 do_setnat: Setting NAT on RTP to Off [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4369 sip_alloc: Allocating new SIP dialog for 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD - INVITE (With RTP) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1706 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces, callerid" [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1714 parse_sip_options: Found SIP option: -timer- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1720 parse_sip_options: Matched SIP option: timer [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1714 parse_sip_options: Found SIP option: -100rel- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1720 parse_sip_options: Matched SIP option: 100rel [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1714 parse_sip_options: Found SIP option: -replaces- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1720 parse_sip_options: Matched SIP option: replaces [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1714 parse_sip_options: Found SIP option: -callerid- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1728 parse_sip_options: Found no match for SIP option: callerid (Please file bug report!) Sending to 192.168.1.254 : 1111 (NAT) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:13420 handle_request_invite: Initializing initreq for method INVITE - callid 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD Using INVITE request as basis request - 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD Found user '101' for '101' [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2670 do_setnat: Setting NAT on RTP to Off <--- Reliably Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-s53c4ufq5a2c;received=192.168.1.254;rport=1111 From: "Sebastian Roesner" ;tag=yl2pk9uifb To: ;tag=as60a18a30 Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1d6d5cb3" Content-Length: 0 <------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1996 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #10 Scheduling destruction of SIP dialog '3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD' in 32000 ms (Method: INVITE) <--- SIP read from 192.168.1.254:1111 ---> SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-7uq0ldc0zdy5;rport From: ;tag=1na1y82fyn To: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 2 SUBSCRIBE Max-Forwards: 70 Contact: ;flow-id=1 Event: dialog;purpose=call-completion Accept: application/dialog-info+xml Authorization: Digest username="101",realm="asterisk",nonce="42a931d6",uri="sip:102@roesner.loc;user=phone",response="3ac307631591949ce607fe88069c2373",algorithm=md5 Expires: 3600 Content-Length: 0 <-------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 48]: SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-7uq0ldc0zdy5;rport [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 42]: From: ;tag=1na1y82fyn [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 36]: To: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 17]: CSeq: 2 SUBSCRIBE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 37]: Event: dialog;purpose=call-completion [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 35]: Accept: application/dialog-info+xml [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [165]: Authorization: Digest username="101",realm="asterisk",nonce="42a931d6",uri="sip:102@roesner.loc;user=phone",response="3ac307631591949ce607fe88069c2373",algorithm=md5 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 13]: Expires: 3600 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 17]: Content-Length: 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 13 [ 0]: --- (13 headers 0 lines) --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14342 handle_request_subscribe: Got a new subscription 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD (possibly with auth) Creating new subscription [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14363 handle_request_subscribe: Initializing initreq for method SUBSCRIBE - callid 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD Sending to 192.168.1.254 : 1111 (NAT) Found peer '101' for '101' from 192.168.1.254:1111 Looking for 102 in local-in (domain roesner.loc) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14523 handle_request_subscribe: Adding subscription for extension 102 context local-in for peer 101 Scheduling destruction of SIP dialog '3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD' in 3610000 ms (Method: SUBSCRIBE) [Jan 12 16:29:23] NOTICE[10757]: chan_sip.c:14542 handle_request_subscribe: Got SUBSCRIBE for extension 102@local-in from 192.168.1.254, but there is no hint for that extension. <--- Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 404 Not found Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-7uq0ldc0zdy5;received=192.168.1.254;rport=1111 From: ;tag=1na1y82fyn To: ;tag=as554c9d64 Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 2 SUBSCRIBE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> Really destroying SIP dialog '3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD' Method: SUBSCRIBE <--- SIP read from 192.168.1.254:1111 ---> ACK sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-s53c4ufq5a2c;rport From: "Sebastian Roesner" ;tag=yl2pk9uifb To: ;tag=as60a18a30 Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 42]: ACK sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-s53c4ufq5a2c;rport [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=yl2pk9uifb [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 51]: To: ;tag=as60a18a30 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 11]: CSeq: 1 ACK [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 17]: Content-Length: 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2095 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2106 __sip_ack: Stopping retransmission on '3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD' of Response 1: Match Found <--- SIP read from 192.168.1.254:1111 ---> INVITE sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-t3jri24n5gbj;rport From: "Sebastian Roesner" ;tag=yl2pk9uifb To: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 2 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/6.5.2 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Authorization: Digest username="101",realm="asterisk",nonce="1d6d5cb3",uri="sip:102@roesner.loc;user=phone",response="f9118db47c023cbf181ec261ab8b2428",algorithm=md5 Content-Type: application/sdp Content-Length: 473 v=0 o=root 96225157 96225157 IN IP4 192.168.1.254 s=call c=IN IP4 192.168.1.254 t=0 0 m=audio 49562 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ieJTxRsjwfyyXXzOkxqj2UOoVlaG9N7/9N6BwTU0 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 45]: INVITE sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-t3jri24n5gbj;rport [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=yl2pk9uifb [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 36]: To: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 41]: P-Key-Flags: resolution="31x13", keys="4" [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 25]: User-Agent: snom360/6.5.2 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 23]: Accept: application/sdp [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 13 [ 44]: Supported: timer, 100rel, replaces, callerid [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 14 [ 35]: Session-Expires: 3600;refresher=uas [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 15 [ 10]: Min-SE: 90 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 16 [165]: Authorization: Digest username="101",realm="asterisk",nonce="1d6d5cb3",uri="sip:102@roesner.loc;user=phone",response="f9118db47c023cbf181ec261ab8b2428",algorithm=md5 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 17 [ 29]: Content-Type: application/sdp [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 18 [ 19]: Content-Length: 473 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 19 [ 0]: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 0 [ 3]: v=0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 1 [ 45]: o=root 96225157 96225157 IN IP4 192.168.1.254 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 2 [ 6]: s=call [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.254 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 4 [ 5]: t=0 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 5 [ 40]: m=audio 49562 RTP/AVP 0 8 9 2 3 18 4 101 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 6 [ 82]: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ieJTxRsjwfyyXXzOkxqj2UOoVlaG9N7/9N6BwTU0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 7 [ 20]: a=rtpmap:0 pcmu/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 8 [ 20]: a=rtpmap:8 pcma/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 9 [ 20]: a=rtpmap:9 g722/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 10 [ 23]: a=rtpmap:2 g726-32/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 11 [ 19]: a=rtpmap:3 gsm/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 12 [ 21]: a=rtpmap:18 g729/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 13 [ 20]: a=rtpmap:4 g723/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 15 [ 15]: a=fmtp:101 0-16 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 16 [ 10]: a=ptime:20 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 17 [ 21]: a=encryption:optional [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 18 [ 10]: a=sendrecv --- (19 headers 19 lines) --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.1.254 : 1111 (NAT) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:13420 handle_request_invite: Initializing initreq for method INVITE - callid 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD Using INVITE request as basis request - 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD Found user '101' for '101' [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2670 do_setnat: Setting NAT on RTP to Off Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 9 Found RTP audio format 2 Found RTP audio format 3 Found RTP audio format 18 Found RTP audio format 4 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.254:49562 Got unsupported a:crypto in SDP offer Found description format pcmu for ID 0 Found description format pcma for ID 8 Found description format g722 for ID 9 Found description format g726-32 for ID 2 Found description format gsm for ID 3 Found description format g729 for ID 18 Found description format g723 for ID 4 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:5166 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x8 (alaw), peer - audio=0x190f (g723|gsm|ulaw|alaw|g726|g729|g722)/video=0x0 (nothing), combined - 0x8 (alaw) 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.254:49562 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:5243 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:13501 handle_request_invite: Checking SIP call limits for device 101 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3093 update_call_counter: Updating call counter for incoming call Looking for 102 in local-in (domain roesner.loc) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3873 sip_new: *** Our native formats are 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3874 sip_new: *** Joint capabilities are 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3875 sip_new: *** Our capabilities are 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3876 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3899 sip_new: This channel will not be able to handle video. [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:7975 build_route: build_route: Contact hop: ;flow-id=1 list_route: hop: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:13576 handle_request_invite: SIP/101-081d5a68: New call is still down.... Trying... <--- Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-t3jri24n5gbj;received=192.168.1.254;rport=1111 From: "Sebastian Roesner" ;tag=yl2pk9uifb To: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081d5a68 [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 101 [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:371 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 101 [Jan 12 16:29:23] DEBUG[10757]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [102@local-in:1] Dial("SIP/101-081d5a68", "SIP/102") in new stack [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:15383 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4369 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2670 do_setnat: Setting NAT on RTP to On [Jan 12 16:29:23] DEBUG[10757]: frame.c:1159 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3873 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3874 sip_new: *** Joint capabilities are 0x0 (nothing) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3875 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Jan 12 16:29:23] DEBUG[10757]: frame.c:1159 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3876 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3878 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3899 sip_new: This channel will not be able to handle video. [Jan 12 16:29:23] DEBUG[10757]: channel.c:3187 ast_channel_inherit_variables: Not copying variable STACK-local-in-102-1. [Jan 12 16:29:23] DEBUG[10757]: channel.c:3187 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jan 12 16:29:23] DEBUG[10757]: channel.c:3187 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jan 12 16:29:23] DEBUG[10757]: channel.c:3187 ast_channel_inherit_variables: Not copying variable SIPURI. [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2919 sip_call: Outgoing Call for 102 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:3093 update_call_counter: Updating call counter for outgoing call [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2936 sip_call: Our T38 capability (0), joint T38 capability (0) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:6246 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:6247 add_sdp: ** Our prefcodec: 0x8 (alaw) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:6264 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at 192.168.1.1 port 15902 Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:6372 add_sdp: -- Done with adding codecs to SDP [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:6416 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1646 initialize_initreq: Initializing initreq for method INVITE - callid 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 55]: INVITE sip:102@192.168.1.249:2051;line=ne6yi1zt SIP/2.0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 62]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 62]: From: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 46]: To: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 30]: Contact: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r50469 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 35]: Date: Fri, 12 Jan 2007 15:29:23 GMT [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 19]: Supported: replaces [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 13 [ 19]: Content-Length: 285 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 14 [ 0]: [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 0 [ 3]: v=0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 1 [ 37]: o=root 10753 10753 IN IP4 192.168.1.1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 2 [ 9]: s=session [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 3 [ 20]: c=IN IP4 192.168.1.1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 4 [ 5]: t=0 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 5 [ 31]: m=audio 15902 RTP/AVP 8 3 0 101 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 12 [ 10]: a=ptime:20 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 13 [ 10]: a=sendrecv Reliably Transmitting (NAT) to 192.168.1.249:2051: INVITE sip:102@192.168.1.249:2051;line=ne6yi1zt SIP/2.0 Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport Max-Forwards: 70 From: "Sebastian Roesner" ;tag=as6416ec21 To: Contact: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r50469 Date: Fri, 12 Jan 2007 15:29:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 285 v=0 o=root 10753 10753 IN IP4 192.168.1.1 s=session c=IN IP4 192.168.1.1 t=0 0 m=audio 15902 RTP/AVP 8 3 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:1996 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 -- Called 102 [Jan 12 16:29:23] DEBUG[10757]: channel.c:2737 set_format: Set channel SIP/102-081d3de8 to read format alaw [Jan 12 16:29:23] DEBUG[10757]: channel.c:2737 set_format: Set channel SIP/101-081d5a68 to read format ulaw [Jan 12 16:29:23] DEBUG[10757]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.1.249:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 From: "Sebastian Roesner" ;tag=as6416ec21 To: ;tag=owkrsnn1vv Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 61]: To: ;tag=owkrsnn1vv [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 17]: Content-Length: 0 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2140 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #13 - INVITE (got response) [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:2149 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39528490249d6abf22cd2ca004bd7088@192.168.1.1' Request 102: Found [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:11737 handle_response_invite: SIP response 180 to standard invite [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-081d3de8 [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 102 [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:371 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Jan 12 16:29:23] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Jan 12 16:29:23] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 102 -- SIP/102-081d3de8 is ringing <--- Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-t3jri24n5gbj;received=192.168.1.254;rport=1111 From: "Sebastian Roesner" ;tag=yl2pk9uifb To: ;tag=as0af609ae Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 16:29:23] DEBUG[10757]: app_queue.c:568 changethread: Device 'SIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.1.249:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 From: "Sebastian Roesner" ;tag=as6416ec21 To: ;tag=owkrsnn1vv Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 61]: To: ;tag=owkrsnn1vv [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 17]: Content-Length: 0 [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:2149 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39528490249d6abf22cd2ca004bd7088@192.168.1.1' Request 102: Found [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:11737 handle_response_invite: SIP response 180 to standard invite -- SIP/102-081d3de8 is ringing <--- SIP read from 192.168.1.2:8304 ---> <-------------> [Jan 12 16:29:24] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 0]: --- (0 headers 0 lines) Nat keepalive --- <--- SIP read from 192.168.1.249:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 From: "Sebastian Roesner" ;tag=as6416ec21 To: ;tag=owkrsnn1vv Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 61]: To: ;tag=owkrsnn1vv [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 17]: Content-Length: 0 [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:2149 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39528490249d6abf22cd2ca004bd7088@192.168.1.1' Request 102: Found [Jan 12 16:29:25] DEBUG[10757]: chan_sip.c:11737 handle_response_invite: SIP response 180 to standard invite -- SIP/102-081d3de8 is ringing <--- SIP read from 192.168.1.249:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 From: "Sebastian Roesner" ;tag=as6416ec21 To: ;tag=owkrsnn1vv Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 61]: To: ;tag=owkrsnn1vv [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 17]: Content-Length: 0 [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:2149 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '39528490249d6abf22cd2ca004bd7088@192.168.1.1' Request 102: Found [Jan 12 16:29:27] DEBUG[10757]: chan_sip.c:11737 handle_response_invite: SIP response 180 to standard invite -- SIP/102-081d3de8 is ringing [Jan 12 16:29:28] DEBUG[10757]: rtp.c:915 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 192.168.1.249:59165 [Jan 12 16:29:28] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.1.249:2051 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 From: "Sebastian Roesner" ;tag=as6416ec21 To: ;tag=owkrsnn1vv Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom360/6.5.3 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Type: application/sdp Content-Length: 329 v=0 o=root 1364781173 1364781174 IN IP4 192.168.1.249 s=call c=IN IP4 192.168.1.249 t=0 0 m=audio 59164 RTP/AVP 8 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ozFHSujfPNY838ZPyDHVh/Lq8l2ZQ2KPXeGjdiFv a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 14]: SIP/2.0 200 Ok [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK19fc3f05;rport=5060 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 61]: To: ;tag=owkrsnn1vv [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 25]: User-Agent: snom360/6.5.3 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 31]: Allow-Events: talk, hold, refer [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 44]: Supported: timer, 100rel, replaces, callerid [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 19]: Content-Length: 329 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 13 [ 0]: [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 0 [ 3]: v=0 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 1 [ 49]: o=root 1364781173 1364781174 IN IP4 192.168.1.249 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 2 [ 6]: s=call [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.249 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 4 [ 5]: t=0 0 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 5 [ 27]: m=audio 59164 RTP/AVP 8 101 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 6 [ 82]: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ozFHSujfPNY838ZPyDHVh/Lq8l2ZQ2KPXeGjdiFv [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 7 [ 20]: a=rtpmap:8 pcma/8000 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 9 [ 15]: a=fmtp:101 0-16 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 10 [ 10]: a=ptime:20 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 11 [ 21]: a=encryption:optional [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Body 12 [ 10]: a=sendrecv --- (13 headers 13 lines) --- [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:2090 __sip_ack: Acked pending invite 102 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:2106 __sip_ack: Stopping retransmission on '39528490249d6abf22cd2ca004bd7088@192.168.1.1' of Request 102: Match Found [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:11737 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 8 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.249:59164 Got unsupported a:crypto in SDP offer Found description format pcma for ID 8 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:5166 process_sdp: T38 state changed to 0 on channel SIP/102-081d3de8 Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) 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.249:59164 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:5243 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:5250 process_sdp: We have an owner, now see if we need to change this call [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:5255 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x8 (alaw) and not 0x4 (ulaw) [Jan 12 16:29:28] DEBUG[10757]: frame.c:1159 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 12 16:29:28] DEBUG[10757]: channel.c:2737 set_format: Set channel SIP/102-081d3de8 to read format alaw [Jan 12 16:29:28] DEBUG[10757]: channel.c:2737 set_format: Set channel SIP/102-081d3de8 to write format ulaw [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:3093 update_call_counter: Updating call counter for outgoing call [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:7975 build_route: build_route: Contact hop: ;flow-id=1 list_route: hop: [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:5681 reqprep: Strict routing enforced for session 39528490249d6abf22cd2ca004bd7088@192.168.1.1 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.249, port 2051 Transmitting (NAT) to 192.168.1.249:2051: ACK sip:102@192.168.1.249:2051;line=ne6yi1zt SIP/2.0 Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK5b07967f;rport Max-Forwards: 70 From: "Sebastian Roesner" ;tag=as6416ec21 To: ;tag=owkrsnn1vv Contact: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r50469 Content-Length: 0 --- [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-081d3de8 -- SIP/102-081d3de8 answered SIP/101-081d5a68 [Jan 12 16:29:28] DEBUG[10757]: channel.c:2737 set_format: Set channel SIP/101-081d5a68 to read format alaw [Jan 12 16:29:28] DEBUG[10757]: channel.c:2737 set_format: Set channel SIP/102-081d3de8 to write format alaw [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 102 [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:371 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 102 [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081d5a68 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:3539 sip_answer: SIP answering channel: SIP/101-081d5a68 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:6471 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:6246 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:6247 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.1.1 port 16416 Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:6372 add_sdp: -- Done with adding codecs to SDP [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:6416 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) <--- Reliably Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-t3jri24n5gbj;received=192.168.1.254;rport=1111 From: "Sebastian Roesner" ;tag=yl2pk9uifb To: ;tag=as0af609ae Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 238 v=0 o=root 10753 10753 IN IP4 192.168.1.1 s=session c=IN IP4 192.168.1.1 t=0 0 m=audio 16416 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:1996 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #15 [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 101 [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:371 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Jan 12 16:29:28] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 101 [Jan 12 16:29:28] DEBUG[10757]: app_queue.c:568 changethread: Device 'SIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 12 16:29:28] DEBUG[10757]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.1.254:1111 ---> ACK sip:102@192.168.1.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-19qolnfgxfla;rport From: "Sebastian Roesner" ;tag=yl2pk9uifb To: ;tag=as0af609ae Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 2 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 31]: ACK sip:102@192.168.1.1 SIP/2.0 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-19qolnfgxfla;rport [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 62]: From: "Sebastian Roesner" ;tag=yl2pk9uifb [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 51]: To: ;tag=as0af609ae [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 11]: CSeq: 2 ACK [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 17]: Content-Length: 0 [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:28] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14897 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) -- Packet2Packet bridging SIP/101-081d5a68 and SIP/102-081d3de8 [Jan 12 16:29:29] DEBUG[10757]: rtp.c:2734 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 12 16:29:29] DEBUG[10757]: rtp.c:2751 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 12 16:29:29] DEBUG[10757]: rtp.c:2734 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 12 16:29:29] DEBUG[10757]: rtp.c:2751 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:2095 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:2106 __sip_ack: Stopping retransmission on '3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD' of Response 2: Match Found <--- SIP read from 192.168.1.254:1111 ---> SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-bmu8kjlo2x6o;rport From: ;tag=1na1y82fyn To: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 3 SUBSCRIBE Max-Forwards: 70 Contact: ;flow-id=1 Event: dialog;purpose=call-completion Accept: application/dialog-info+xml Expires: 0 Content-Length: 0 <-------------> [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 48]: SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-bmu8kjlo2x6o;rport [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 42]: From: ;tag=1na1y82fyn [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 36]: To: [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 17]: CSeq: 3 SUBSCRIBE [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 37]: Event: dialog;purpose=call-completion [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 35]: Accept: application/dialog-info+xml [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 10]: Expires: 0 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 17]: Content-Length: 0 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4369 sip_alloc: Allocating new SIP dialog for 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD - SUBSCRIBE (No RTP) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Creating new subscription [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14363 handle_request_subscribe: Initializing initreq for method SUBSCRIBE - callid 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD Sending to 192.168.1.254 : 1111 (NAT) Found peer '101' for '101' from 192.168.1.254:1111 <--- Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-bmu8kjlo2x6o;received=192.168.1.254;rport=1111 From: ;tag=1na1y82fyn To: ;tag=as359553cf Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 3 SUBSCRIBE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="632f10cd" Content-Length: 0 <------------> Scheduling destruction of SIP dialog '3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD' in 32000 ms (Method: SUBSCRIBE) <--- SIP read from 192.168.1.254:1111 ---> SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-ed1phhbqrjby;rport From: ;tag=1na1y82fyn To: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 4 SUBSCRIBE Max-Forwards: 70 Contact: ;flow-id=1 Event: dialog;purpose=call-completion Accept: application/dialog-info+xml Authorization: Digest username="101",realm="asterisk",nonce="632f10cd",uri="sip:102@roesner.loc;user=phone",response="8aa4d2e12527b875abd7674a6439813a",algorithm=md5 Expires: 0 Content-Length: 0 <-------------> [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 48]: SUBSCRIBE sip:102@roesner.loc;user=phone SIP/2.0 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-ed1phhbqrjby;rport [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 42]: From: ;tag=1na1y82fyn [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 36]: To: [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 17]: CSeq: 4 SUBSCRIBE [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 37]: Event: dialog;purpose=call-completion [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 35]: Accept: application/dialog-info+xml [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [165]: Authorization: Digest username="101",realm="asterisk",nonce="632f10cd",uri="sip:102@roesner.loc;user=phone",response="8aa4d2e12527b875abd7674a6439813a",algorithm=md5 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 10]: Expires: 0 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 17]: Content-Length: 0 [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 13 [ 0]: --- (13 headers 0 lines) --- [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14342 handle_request_subscribe: Got a new subscription 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD (possibly with auth) Creating new subscription [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14363 handle_request_subscribe: Initializing initreq for method SUBSCRIBE - callid 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD Sending to 192.168.1.254 : 1111 (NAT) Found peer '101' for '101' from 192.168.1.254:1111 Looking for 102 in local-in (domain roesner.loc) [Jan 12 16:29:29] DEBUG[10757]: chan_sip.c:14523 handle_request_subscribe: Adding subscription for extension 102 context local-in for peer 101 [Jan 12 16:29:29] NOTICE[10757]: chan_sip.c:14542 handle_request_subscribe: Got SUBSCRIBE for extension 102@local-in from 192.168.1.254, but there is no hint for that extension. <--- Transmitting (no NAT) to 192.168.1.254:1111 ---> SIP/2.0 404 Not found Via: SIP/2.0/UDP 192.168.1.254:1111;branch=z9hG4bK-ed1phhbqrjby;received=192.168.1.254;rport=1111 From: ;tag=1na1y82fyn To: ;tag=as359553cf Call-ID: 3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD CSeq: 4 SUBSCRIBE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> Really destroying SIP dialog '3c2b4e0c445c-h45gqkpqdf7s@snom360-000413233BAD' Method: SUBSCRIBE <--- SIP read from 192.168.1.2:8304 ---> <-------------> [Jan 12 16:29:33] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 0]: --- (0 headers 0 lines) Nat keepalive --- [Jan 12 16:29:33] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes [Jan 12 16:29:33] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes si[Jan 12 16:29:38] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes [Jan 12 16:29:38] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes p show channels Peer User/ANR Call ID Seq (Tx/Rx) Form Hold Last Message 192.168.1.249 102 39528490249 00102/00000 alaw No Tx: ACK 192.168.1.254 101 3c2b4e0c445 00101/00002 alaw No Rx: ACK 2 active SIP channels *CLI> <--- SIP read from 192.168.1.2:8304 ---> <-------------> [Jan 12 16:29:42] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 0]: --- (0 headers 0 lines) Nat keepalive --- [Jan 12 16:29:43] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes [Jan 12 16:29:43] DEBUG[10757]: rtp.c:920 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.1.249:2051 ---> BYE sip:101@192.168.1.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.249:2051;branch=z9hG4bK-tyccvw21arf0;rport From: ;tag=owkrsnn1vv To: "Sebastian Roesner" ;tag=as6416ec21 Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 1 BYE Max-Forwards: 70 Contact: ;flow-id=1 User-Agent: snom360/6.5.3 RTP-RxStat: Total_Rx_Pkts=745,Rx_Pkts=745,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=762,Tx_Pkts=762,Remote_Tx_Pkts=500 Content-Length: 0 <-------------> [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 31]: BYE sip:101@192.168.1.1 SIP/2.0 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.249:2051;branch=z9hG4bK-tyccvw21arf0;rport [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 63]: From: ;tag=owkrsnn1vv [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 60]: To: "Sebastian Roesner" ;tag=as6416ec21 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 53]: Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 11]: CSeq: 1 BYE [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 25]: User-Agent: snom360/6.5.3 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 78]: RTP-RxStat: Total_Rx_Pkts=745,Rx_Pkts=745,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 60]: RTP-TxStat: Total_Tx_Pkts=762,Tx_Pkts=762,Remote_Tx_Pkts=500 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 17]: Content-Length: 0 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:14709 handle_request: **** Received BYE (8) - Command in SIP BYE [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:14242 handle_request_bye: Initializing initreq for method BYE - callid 39528490249d6abf22cd2ca004bd7088@192.168.1.1 Sending to 192.168.1.249 : 2051 (NAT) [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:1659 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 39528490249d6abf22cd2ca004bd7088@192.168.1.1 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:14292 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 192.168.1.249:2051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.249:2051;branch=z9hG4bK-tyccvw21arf0;received=192.168.1.249;rport=2051 From: ;tag=owkrsnn1vv To: "Sebastian Roesner" ;tag=as6416ec21 Call-ID: 39528490249d6abf22cd2ca004bd7088@192.168.1.1 CSeq: 1 BYE User-Agent: Asterisk PBX SVN-trunk-r50469 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 12 16:29:44] DEBUG[10757]: rtp.c:3121 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup [Jan 12 16:29:44] DEBUG[10757]: channel.c:3942 ast_channel_bridge: Returning from native bridge, channels: SIP/101-081d5a68, SIP/102-081d3de8 [Jan 12 16:29:44] DEBUG[10757]: channel.c:1592 ast_hangup: Hanging up channel 'SIP/102-081d3de8' [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:3391 sip_hangup: Hangup call SIP/102-081d3de8, SIP callid 39528490249d6abf22cd2ca004bd7088@192.168.1.1) [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:3399 sip_hangup: update_call_counter(102) - decrement call limit counter on hangup [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:3093 update_call_counter: Updating call counter for outgoing call [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-081d3de8 [Jan 12 16:29:44] DEBUG[10757]: rtp.c:1537 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jan 12 16:29:44] DEBUG[10757]: app_dial.c:1682 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jan 12 16:29:44] DEBUG[10757]: pbx.c:2289 __ast_pbx_run: Spawn extension (local-in,102,1) exited non-zero on 'SIP/101-081d5a68' == Spawn extension (local-in, 102, 1) exited non-zero on 'SIP/101-081d5a68' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"Sebastian Roesner" <101>' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '101' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '102' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'local-in' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081d5a68' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/102-081d3de8' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Dial' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/102' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-01-12 16:29:23' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-01-12 16:29:28' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-01-12 16:29:44' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '21' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '16' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1168615763.0' [Jan 12 16:29:44] DEBUG[10757]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Jan 12 16:29:44] DEBUG[10757]: channel.c:1592 ast_hangup: Hanging up channel 'SIP/101-081d5a68' [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:3391 sip_hangup: Hangup call SIP/101-081d5a68, SIP callid 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD) [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:3399 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:3093 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog '3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD' in 32000 ms (Method: ACK) [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:5681 reqprep: Strict routing enforced for session 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.254, port 1111 Reliably Transmitting (no NAT) to 192.168.1.254:1111: BYE sip:101@192.168.1.254:1111;line=gv8x1x75 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK6fa920d6;rport Max-Forwards: 70 From: ;tag=as0af609ae To: "Sebastian Roesner" ;tag=yl2pk9uifb Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 102 BYE User-Agent: Asterisk PBX SVN-trunk-r50469 Content-Length: 0 --- [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:1996 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #20 [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081d5a68 [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 102 [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:371 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 102 [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 101 [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:371 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Jan 12 16:29:44] DEBUG[10757]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:15325 sip_devicestate: Checking device state for peer 101 [Jan 12 16:29:44] DEBUG[10757]: app_queue.c:568 changethread: Device 'SIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 12 16:29:44] DEBUG[10757]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.1.254:1111 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK6fa920d6;rport=5060 From: ;tag=as0af609ae To: "Sebastian Roesner" ;tag=yl2pk9uifb Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD CSeq: 102 BYE Contact: ;flow-id=1 User-Agent: snom360/6.5.2 RTP-RxStat: Total_Rx_Pkts=755,Rx_Pkts=755,Rx_Pkts_Lost=8,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=786,Tx_Pkts=786,Remote_Tx_Pkts=753 Content-Length: 0 <-------------> [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP 192.168.1.1:5060;branch=z9hG4bK6fa920d6;rport=5060 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 2 [ 53]: From: ;tag=as0af609ae [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 3 [ 60]: To: "Sebastian Roesner" ;tag=yl2pk9uifb [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 4 [ 55]: Call-ID: 3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 5 [ 13]: CSeq: 102 BYE [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 7 [ 25]: User-Agent: snom360/6.5.2 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 8 [ 78]: RTP-RxStat: Total_Rx_Pkts=755,Rx_Pkts=755,Rx_Pkts_Lost=8,Remote_Rx_Pkts_Lost=0 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 9 [ 60]: RTP-TxStat: Total_Tx_Pkts=786,Tx_Pkts=786,Remote_Tx_Pkts=753 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 10 [ 17]: Content-Length: 0 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:4647 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:2095 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #20 [Jan 12 16:29:44] DEBUG[10757]: chan_sip.c:2106 __sip_ack: Stopping retransmission on '3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD' of Request 102: Match Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '39528490249d6abf22cd2ca004bd7088@192.168.1.1' Method: BYE Really destroying SIP dialog '3c2b4e0c445c-ka9z8u1zti3l@snom360-000413233BAD' Method: ACK stop now