<--- SIP read from 192.168.170.244:5060 ---> INVITE sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95800003e0d000000fa Content-Length: 343 Contact: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=9024198410510 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3381032920 3381032920 IN IP4 192.168.170.244 s=SJphone c=IN IP4 192.168.170.244 t=0 0 a=direction:active m=audio 49154 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95800003e0d000000fa [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 19]: Content-Length: 343 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 39]: Contact: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 58]: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 14]: CSeq: 1 INVITE [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 62]: From: "unknown";tag=9024198410510 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 33]: To: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 0]: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 48]: o=- 3381032920 3381032920 IN IP4 192.168.170.244 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 9]: s=SJphone [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 18]: a=direction:active [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 37]: m=audio 49154 RTP/AVP 3 97 98 8 0 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 14 lines) --- [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 (Checking From) --From tag 9024198410510 --To-tag [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 84CA7AE1-137A-4ADA-8E7D-4672D470CFD0@192.168.4.11 Their Tag 902417346395 Our tag: as6e51c4a5 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9024009316337 Our tag: as2e5710c2 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9022009311421 Our tag: as2d223c4e [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to Off [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to Off [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to Off [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 - INVITE (With RTP) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:13959 handle_request_invite: Initializing initreq for method INVITE - callid 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Using INVITE request as basis request - 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.170.244:5060 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to On [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On <--- Reliably Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000004e45dbf95800003e0d000000fa;received=192.168.170.244;rport=5060 From: "unknown";tag=9024198410510 To: ;tag=as4a9e5ce8 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4bdd7a2f" Content-Length: 0 <------------> [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #152 Scheduling destruction of SIP dialog '3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11' in 6848 ms (Method: INVITE) <--- SIP read from 192.168.170.244:5060 ---> ACK sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95800003e0d000000fa Content-Length: 0 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 1 ACK From: "unknown";tag=9024198410510 Max-Forwards: 70 To: ;tag=as4a9e5ce8 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: ACK sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95800003e0d000000fa [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 62]: From: "unknown";tag=9024198410510 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 48]: To: ;tag=as4a9e5ce8 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 (Checking From) --From tag 9024198410510 --To-tag as4a9e5ce8 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Their Tag 9024198410510 Our tag: as4a9e5ce8 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #152 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11' of Response 1: Match Found <--- SIP read from 192.168.170.244:5060 ---> INVITE sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95800002d9d000000fb Content-Length: 343 Contact: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=9024198410510 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Authorization: Digest username="101",realm="asterisk",nonce="4bdd7a2f",uri="sip:103@192.168.168.35:5060",response="928cedaa8fbcf7015c6f3044512d99c7",algorithm="MD5" v=0 o=- 3381032920 3381032920 IN IP4 192.168.170.244 s=SJphone c=IN IP4 192.168.170.244 t=0 0 a=direction:active m=audio 49154 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95800002d9d000000fb [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 19]: Content-Length: 343 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 39]: Contact: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 58]: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 14]: CSeq: 2 INVITE [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 62]: From: "unknown";tag=9024198410510 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 33]: To: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [164]: Authorization: Digest username="101",realm="asterisk",nonce="4bdd7a2f",uri="sip:103@192.168.168.35:5060",response="928cedaa8fbcf7015c6f3044512d99c7",algorithm="MD5" [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 0]: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 48]: o=- 3381032920 3381032920 IN IP4 192.168.170.244 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 9]: s=SJphone [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 18]: a=direction:active [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 37]: m=audio 49154 RTP/AVP 3 97 98 8 0 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (12 headers 14 lines) --- [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 (Checking From) --From tag 9024198410510 --To-tag [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Their Tag 9024198410510 Our tag: as4a9e5ce8 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:13959 handle_request_invite: Initializing initreq for method INVITE - callid 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Using INVITE request as basis request - 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.170.244:5060 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to On [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On Found RTP audio format 3 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:5266 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.170.244:49154 Found description format GSM for ID 3 Found description format iLBC for ID 97 Found description format iLBC for ID 98 Got unsupported a:fmtp in SDP offer Found description format PCMA for ID 8 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:5508 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x4 (ulaw), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.170.244:49154 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:5599 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:14040 handle_request_invite: Checking SIP call limits for device 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for incoming call [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:3374 update_call_counter: Call from peer '101' is 1 out of 2 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 Looking for 103 in from-sip (domain 192.168.168.35) [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4118 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4119 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4120 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4121 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4151 sip_new: This channel will not be able to handle video. [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:8462 build_route: build_route: Contact hop: list_route: hop: [Feb 21 08:47:27] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:14115 handle_request_invite: SIP/101-081bf218: New call is still down.... Trying... <--- Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000004e45dbf95800002d9d000000fb;received=192.168.170.244;rport=5060 From: "unknown";tag=9024198410510 To: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081bf218 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:27] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'NOT_INUSE' [Feb 21 08:47:27] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:1] NoOp("SIP/101-081bf218", "SIP/103 has state NOT_INUSE") in new stack [Feb 21 08:47:27] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:47:27] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '0' [Feb 21 08:47:27] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:2] NoOp("SIP/101-081bf218", "SIPPEER(103:curcalls) is 0") in new stack [Feb 21 08:47:27] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [103@from-sip:3] Dial("SIP/101-081bf218", "SIP/103") in new stack [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15950 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2896 create_addr_from_peer: Our T38 capability (3856) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:1782 obproxy_get: OBPROXY: Not applying OBproxy to this call [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4118 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4119 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4120 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4121 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4123 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4151 sip_new: This channel will not be able to handle video. [Feb 21 08:47:27] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-3. [Feb 21 08:47:27] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-2. [Feb 21 08:47:27] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-1. [Feb 21 08:47:27] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 21 08:47:27] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 21 08:47:27] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:3121 sip_call: Outgoing Call for 103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for outgoing call [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:3374 update_call_counter: Call to peer '103' is 1 out of 2 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:3139 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:6658 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:27] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:6660 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.5.1 port 17818 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:6821 add_sdp: -- Done with adding codecs to SDP [Feb 21 08:47:27] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:6881 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:1717 initialize_initreq: Initializing initreq for method INVITE - callid 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 38]: INVITE sip:103@172.24.0.2:5060 SIP/2.0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 59]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208;rport [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 49]: From: "unknown" ;tag=as573b29e7 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 29]: To: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 27]: Contact: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 50]: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r55495 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 35]: Date: Wed, 21 Feb 2007 07:47:27 GMT [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 19]: Supported: replaces [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 13 [ 19]: Content-Length: 232 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 14 [ 0]: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 34]: o=root 25965 25965 IN IP4 10.1.5.1 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 9]: s=session [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 17]: c=IN IP4 10.1.5.1 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 27]: m=audio 17818 RTP/AVP 0 101 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (NAT) to 10.1.10.11:5060: INVITE sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208;rport Max-Forwards: 70 From: "unknown" ;tag=as573b29e7 To: Contact: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Date: Wed, 21 Feb 2007 07:47:27 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 232 v=0 o=root 25965 25965 IN IP4 10.1.5.1 s=session c=IN IP4 10.1.5.1 t=0 0 m=audio 17818 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #154 -- Called 103 <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 100 Trying To: From: "unknown" ;tag=as573b29e7 Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 29]: To: [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as573b29e7 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 (Checking To) --From tag as573b29e7 --To-tag [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag Our tag: as573b29e7 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2267 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #154 - INVITE (got response) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2276 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0b247ed9163fd938790a3047262c6c95@10.1.5.1' Request 102: Found [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:12271 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 180 Ringing To: ;tag=4ce33b8fd646ff2i0 From: "unknown" ;tag=as573b29e7 Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 51]: To: ;tag=4ce33b8fd646ff2i0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as573b29e7 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 (Checking To) --From tag as573b29e7 --To-tag 4ce33b8fd646ff2i0 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag Our tag: as573b29e7 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:2276 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0b247ed9163fd938790a3047262c6c95@10.1.5.1' Request 102: Found [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:12271 handle_response_invite: SIP response 180 to standard invite [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081c3188 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Feb 21 08:47:27] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:27] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 -- SIP/103-081c3188 is ringing <--- Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000004e45dbf95800002d9d000000fb;received=192.168.170.244;rport=5060 From: "unknown";tag=9024198410510 To: ;tag=as55b9b914 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:47:27] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. sip show inuse * User name In use Limit * Peer name In use Limit 103 1/1/0 2 102 0/0/0 2 101 1/0/0 2 *CLI> <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 200 OK To: ;tag=4ce33b8fd646ff2i0 From: "unknown" ;tag=as573b29e7 Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208 Contact: "sip2" Server: Linksys/SPA901-4.1.11(c) Content-Length: 204 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 8870838 8870838 IN IP4 172.24.0.2 s=- c=IN IP4 172.24.0.2 t=0 0 m=audio 16440 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 51]: To: ;tag=4ce33b8fd646ff2i0 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as573b29e7 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK695a6208 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 41]: Contact: "sip2" [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 19]: Content-Length: 204 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 0]: [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 37]: o=- 8870838 8870838 IN IP4 172.24.0.2 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 3]: s=- [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 19]: c=IN IP4 172.24.0.2 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 27]: m=audio 16440 RTP/AVP 0 101 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 10]: a=ptime:30 --- (11 headers 10 lines) --- [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 (Checking To) --From tag as573b29e7 --To-tag 4ce33b8fd646ff2i0 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag 4ce33b8fd646ff2i0 Our tag: as573b29e7 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:2217 __sip_ack: Acked pending invite 102 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '0b247ed9163fd938790a3047262c6c95@10.1.5.1' of Request 102: Match Found [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:12271 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:5266 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 172.24.0.2:16440 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:5508 process_sdp: T38 state changed to 0 on channel SIP/103-081c3188 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 172.24.0.2:16440 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:5599 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:5606 process_sdp: We have an owner, now see if we need to change this call [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for outgoing call [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:8462 build_route: build_route: Contact hop: "sip2" list_route: hop: [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:6034 reqprep: Strict routing enforced for session 0b247ed9163fd938790a3047262c6c95@10.1.5.1 set_destination: Parsing for address/port to send to set_destination: set destination to 172.24.0.2, port 5060 Transmitting (NAT) to 10.1.10.11:5060: ACK sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK472b09a5;rport Max-Forwards: 70 From: "unknown" ;tag=as573b29e7 To: ;tag=4ce33b8fd646ff2i0 Contact: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r55495 Content-Length: 0 --- [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:47:34] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 -- Call on SIP/103-081c3188 left from hold [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081c3188 -- SIP/103-081c3188 answered SIP/101-081bf218 [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:34] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081bf218 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:3753 sip_answer: SIP answering channel: SIP/101-081bf218 [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 21 08:47:34] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:6936 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 21 08:47:34] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:6658 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:6660 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.168.35 port 13550 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:6821 add_sdp: -- Done with adding codecs to SDP [Feb 21 08:47:34] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:6881 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000004e45dbf95800002d9d000000fb;received=192.168.170.244;rport=5060 From: "unknown";tag=9024198410510 To: ;tag=as55b9b914 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 25965 25965 IN IP4 192.168.168.35 s=session c=IN IP4 192.168.168.35 t=0 0 m=audio 13550 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #156 <--- SIP read from 192.168.170.244:5060 ---> ACK sip:103@192.168.168.35 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95f00006bf3000000ff Content-Length: 0 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=9024198410510 Max-Forwards: 70 To: ;tag=as55b9b914 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000004e45dbf95f00006bf3000000ff [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 62]: From: "unknown";tag=9024198410510 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 48]: To: ;tag=as55b9b914 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 (Checking From) --From tag 9024198410510 --To-tag as55b9b914 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag 4ce33b8fd646ff2i0 Our tag: as573b29e7 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Their Tag 9024198410510 Our tag: as55b9b914 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #156 [Feb 21 08:47:34] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11' of Response 2: Match Found -- Packet2Packet bridging SIP/101-081bf218 and SIP/103-081c3188 [Feb 21 08:47:35] DEBUG[25969]: rtp.c:1220 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 10.1.10.11:16440 [Feb 21 08:47:37] DEBUG[25969]: chan_sip.c:2160 __sip_autodestruct: Auto destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' [Feb 21 08:47:37] DEBUG[25969]: chan_sip.c:3400 sip_destroy: Destroying SIP dialog D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Really destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' Method: OPTIONS sip show inuse * User name In use Limit * Peer name In use Limit 103 1/0/0 2 102 0/0/0 2 101 1/0/0 2 *CLI> <--- SIP read from 192.168.170.244:5060 ---> OPTIONS sip:192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45dbf96a000035bd00000100 Content-Length: 0 Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 CSeq: 71 OPTIONS From: ;tag=9026009332723 Max-Forwards: 70 To: <-------------> [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45dbf96a000035bd00000100 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 71 OPTIONS [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: From: ;tag=9026009332723 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 29]: To: --- (8 headers 0 lines) --- [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 (Checking From) --From tag 9026009332723 --To-tag [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag 4ce33b8fd646ff2i0 Our tag: as573b29e7 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Their Tag 9024198410510 Our tag: as55b9b914 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 84CA7AE1-137A-4ADA-8E7D-4672D470CFD0@192.168.4.11 Their Tag 902417346395 Our tag: as6e51c4a5 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9024009316337 Our tag: as2e5710c2 [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 - OPTIONS (No RTP) [Feb 21 08:47:45] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.168.35) <--- Transmitting (no NAT) to 192.168.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000000b45dbf96a000035bd00000100;received=192.168.170.244;rport=5060 From: ;tag=9026009332723 To: ;tag=as5a9e322b Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 CSeq: 71 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' in 32000 ms (Method: OPTIONS) <--- SIP read from 10.1.10.11:5060 ---> BYE sip:101@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-a29056eb From: ;tag=4ce33b8fd646ff2i0 To: "unknown" ;tag=as573b29e7 Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 101 BYE Max-Forwards: 70 User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 28]: BYE sip:101@10.1.5.1 SIP/2.0 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-a29056eb [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 53]: From: ;tag=4ce33b8fd646ff2i0 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 47]: To: "unknown" ;tag=as573b29e7 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 50]: Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 13]: CSeq: 101 BYE [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 17]: Content-Length: 0 --- (9 headers 0 lines) --- [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 (Checking From) --From tag 4ce33b8fd646ff2i0 --To-tag as573b29e7 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9026009332723 Our tag: as5a9e322b [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag 4ce33b8fd646ff2i0 Our tag: as573b29e7 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:14781 handle_request_bye: Initializing initreq for method BYE - callid 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Sending to 10.1.10.11 : 5060 (NAT) [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:1730 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0b247ed9163fd938790a3047262c6c95@10.1.5.1 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:14838 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 10.1.10.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-a29056eb;received=10.1.10.11 From: ;tag=4ce33b8fd646ff2i0 To: "unknown" ;tag=as573b29e7 Call-ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 CSeq: 101 BYE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:47:46] DEBUG[25969]: rtp.c:3213 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup [Feb 21 08:47:46] DEBUG[25969]: channel.c:3971 ast_channel_bridge: Returning from native bridge, channels: SIP/101-081bf218, SIP/103-081c3188 [Feb 21 08:47:46] DEBUG[25969]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/103-081c3188' [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3597 sip_hangup: Hangup call SIP/103-081c3188, SIP callid 0b247ed9163fd938790a3047262c6c95@10.1.5.1) [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3605 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for outgoing call [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3348 update_call_counter: Call to peer '103' removed from call limit 2 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081c3188 [Feb 21 08:47:46] DEBUG[25969]: rtp.c:1566 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 21 08:47:46] DEBUG[25969]: app_dial.c:1710 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 21 08:47:46] DEBUG[25969]: pbx.c:2289 __ast_pbx_run: Spawn extension (from-sip,103,3) exited non-zero on 'SIP/101-081bf218' == Spawn extension (from-sip, 103, 3) exited non-zero on 'SIP/101-081bf218' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"unknown" <101>' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '101' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '103' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081bf218' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103-081c3188' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-21 08:47:27' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-21 08:47:34' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-21 08:47:46' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '19' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '12' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1172044047.0' [Feb 21 08:47:46] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 08:47:46] DEBUG[25969]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/101-081bf218' [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3597 sip_hangup: Hangup call SIP/101-081bf218, SIP callid 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11) [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3605 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for incoming call [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:3348 update_call_counter: Call from peer '101' removed from call limit 2 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 Scheduling destruction of SIP dialog '3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11' in 6848 ms (Method: ACK) [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:6034 reqprep: Strict routing enforced for session 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.170.244, port 5060 Reliably Transmitting (NAT) to 192.168.170.244:5060: BYE sip:101@192.168.170.244:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.168.35:5060;branch=z9hG4bK480b71de;rport Max-Forwards: 70 From: ;tag=as55b9b914 To: "unknown";tag=9024198410510 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 102 BYE User-Agent: Asterisk PBX SVN-trunk-r55495 Content-Length: 0 --- [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #159 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081bf218 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Feb 21 08:47:46] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:46] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Feb 21 08:47:46] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:47:46] DEBUG[25969]: 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. [Feb 21 08:47:46] DEBUG[25969]: 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.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.168.35:5060;rport=5060;received=192.168.168.35;branch=z9hG4bK480b71de Content-Length: 0 Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 CSeq: 102 BYE From: ;tag=as55b9b914 Server: SJphone/1.60.289a (SJ Labs) To: "unknown";tag=9024198410510 <-------------> [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 192.168.168.35:5060;rport=5060;received=192.168.168.35;branch=z9hG4bK480b71de [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 13]: CSeq: 102 BYE [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 50]: From: ;tag=as55b9b914 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 35]: Server: SJphone/1.60.289a (SJ Labs) [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 60]: To: "unknown";tag=9024198410510 --- (8 headers 0 lines) --- [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 (Checking To) --From tag as55b9b914 --To-tag 9024198410510 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9026009332723 Our tag: as5a9e322b [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 0b247ed9163fd938790a3047262c6c95@10.1.5.1 Their Tag 4ce33b8fd646ff2i0 Our tag: as573b29e7 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11 Their Tag 9024198410510 Our tag: as55b9b914 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #159 [Feb 21 08:47:46] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11' of Request 102: Match Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '0b247ed9163fd938790a3047262c6c95@10.1.5.1' Method: BYE Really destroying SIP dialog '3A84B206-1BD6-47B6-9D1A-F04D3B525E7C@192.168.4.11' Method: ACK sip show inuse * User name In use Limit * Peer name In use Limit 103 0/0/0 2 102 0/0/0 2 101 0/0/0 2 *CLI> <--- SIP read from 10.1.10.11:5060 ---> INVITE sip:1566@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-365e80ef From: "sip2" ;tag=532ae57e184bc26eo0 To: Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 101 INVITE Max-Forwards: 70 Contact: "sip2" Expires: 240 User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 393 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 8873813 8873813 IN IP4 172.24.0.2 s=- c=IN IP4 172.24.0.2 t=0 0 m=audio 16442 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 32]: INVITE sip:1566@10.1.5.1 SIP/2.0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-365e80ef [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 54]: From: "sip2" ;tag=532ae57e184bc26eo0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 23]: To: [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 37]: Call-ID: 7f46aebe-88208a2e@172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 16]: CSeq: 101 INVITE [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 41]: Contact: "sip2" [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 12]: Expires: 240 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 19]: Content-Length: 393 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 13 [ 0]: [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 37]: o=- 8873813 8873813 IN IP4 172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 3]: s=- [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 19]: c=IN IP4 172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 45]: m=audio 16442 RTP/AVP 0 2 4 8 18 96 97 98 101 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 23]: a=rtpmap:2 G726-32/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 20]: a=rtpmap:4 G723/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 16 [ 10]: a=ptime:30 --- (13 headers 17 lines) --- [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 7f46aebe-88208a2e@172.24.0.2 (Checking From) --From tag 532ae57e184bc26eo0 --To-tag [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9026009332723 Our tag: as5a9e322b [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 84CA7AE1-137A-4ADA-8E7D-4672D470CFD0@192.168.4.11 Their Tag 902417346395 Our tag: as6e51c4a5 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9024009316337 Our tag: as2e5710c2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to Off [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to Off [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to Off [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for 7f46aebe-88208a2e@172.24.0.2 - INVITE (With RTP) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 172.24.0.2 : 5060 (no NAT) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:13959 handle_request_invite: Initializing initreq for method INVITE - callid 7f46aebe-88208a2e@172.24.0.2 Using INVITE request as basis request - 7f46aebe-88208a2e@172.24.0.2 No user '103' in SIP users list Found peer '103' for '103' from 10.1.10.11:5060 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to On [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On <--- Reliably Transmitting (NAT) to 10.1.10.11:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-365e80ef;received=10.1.10.11 From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as743e4ba5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 101 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="068a1a58" Content-Length: 0 <------------> [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #160 Scheduling destruction of SIP dialog '7f46aebe-88208a2e@172.24.0.2' in 2624 ms (Method: INVITE) <--- SIP read from 10.1.10.11:5060 ---> ACK sip:1566@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-365e80ef From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as743e4ba5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 101 ACK Max-Forwards: 70 Contact: "sip2" User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 29]: ACK sip:1566@10.1.5.1 SIP/2.0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-365e80ef [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 54]: From: "sip2" ;tag=532ae57e184bc26eo0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 38]: To: ;tag=as743e4ba5 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 37]: Call-ID: 7f46aebe-88208a2e@172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 13]: CSeq: 101 ACK [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 41]: Contact: "sip2" [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 7f46aebe-88208a2e@172.24.0.2 (Checking From) --From tag 532ae57e184bc26eo0 --To-tag as743e4ba5 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as743e4ba5 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #160 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '7f46aebe-88208a2e@172.24.0.2' of Response 101: Match Found <--- SIP read from 10.1.10.11:5060 ---> INVITE sip:1566@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-fd0097a8 From: "sip2" ;tag=532ae57e184bc26eo0 To: Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="103",realm="asterisk",nonce="068a1a58",uri="sip:1566@10.1.5.1",algorithm=MD5,response="53bcae987f0bfdabd8e9542a63907771" Contact: "sip2" Expires: 240 User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 393 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 8873813 8873813 IN IP4 172.24.0.2 s=- c=IN IP4 172.24.0.2 t=0 0 m=audio 16442 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 32]: INVITE sip:1566@10.1.5.1 SIP/2.0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-fd0097a8 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 54]: From: "sip2" ;tag=532ae57e184bc26eo0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 23]: To: [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 37]: Call-ID: 7f46aebe-88208a2e@172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [152]: Authorization: Digest username="103",realm="asterisk",nonce="068a1a58",uri="sip:1566@10.1.5.1",algorithm=MD5,response="53bcae987f0bfdabd8e9542a63907771" [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 41]: Contact: "sip2" [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 12]: Expires: 240 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 19]: Content-Length: 393 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 14 [ 0]: [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 37]: o=- 8873813 8873813 IN IP4 172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 3]: s=- [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 19]: c=IN IP4 172.24.0.2 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 45]: m=audio 16442 RTP/AVP 0 2 4 8 18 96 97 98 101 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 23]: a=rtpmap:2 G726-32/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 20]: a=rtpmap:4 G723/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 16 [ 10]: a=ptime:30 --- (14 headers 17 lines) --- [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 7f46aebe-88208a2e@172.24.0.2 (Checking From) --From tag 532ae57e184bc26eo0 --To-tag [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as743e4ba5 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.10.11 : 5060 (NAT) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:13959 handle_request_invite: Initializing initreq for method INVITE - callid 7f46aebe-88208a2e@172.24.0.2 Using INVITE request as basis request - 7f46aebe-88208a2e@172.24.0.2 No user '103' in SIP users list Found peer '103' for '103' from 10.1.10.11:5060 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to On [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On Found RTP audio format 0 Found RTP audio format 2 Found RTP audio format 4 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 96 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 101 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:5266 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 172.24.0.2:16442 Found description format PCMU for ID 0 Found description format G726-32 for ID 2 Found description format G723 for ID 4 Found description format PCMA for ID 8 Found description format G729a for ID 18 Found description format G726-40 for ID 96 Found description format G726-24 for ID 97 Found description format G726-16 for ID 98 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:5508 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x4 (ulaw), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 172.24.0.2:16442 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:5599 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:14040 handle_request_invite: Checking SIP call limits for device 103 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for incoming call [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:3374 update_call_counter: Call from peer '103' is 1 out of 2 [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 Looking for 1566 in from-sip (domain 10.1.5.1) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4118 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4119 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4120 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4121 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:4151 sip_new: This channel will not be able to handle video. [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:8462 build_route: build_route: Contact hop: "sip2" list_route: hop: [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:14115 handle_request_invite: SIP/103-b781ee20: New call is still down.... Trying... <--- Transmitting (NAT) to 10.1.10.11:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-fd0097a8;received=10.1.10.11 From: "sip2" ;tag=532ae57e184bc26eo0 To: Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-b781ee20 [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:57] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:47:57] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:47:57] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'NoCDR' [Feb 21 08:47:57] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- Executing [1566@from-sip:1] NoCDR("SIP/103-b781ee20", "") in new stack [Feb 21 08:47:57] NOTICE[25969]: cdr.c:429 ast_cdr_free: CDR on channel 'SIP/103-b781ee20' not posted [Feb 21 08:47:57] NOTICE[25969]: cdr.c:431 ast_cdr_free: CDR on channel 'SIP/103-b781ee20' lacks end [Feb 21 08:47:57] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'PlayTones' -- Executing [1566@from-sip:2] PlayTones("SIP/103-b781ee20", "ring") in new stack [Feb 21 08:47:57] DEBUG[25969]: channel.c:2500 ast_prod: Prodding channel 'SIP/103-b781ee20' [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:6936 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:6658 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:6660 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.1.5.1 port 13110 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:6821 add_sdp: -- Done with adding codecs to SDP [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:6881 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Transmitting (NAT) to 10.1.10.11:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-fd0097a8;received=10.1.10.11 From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as30ec28d5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 232 v=0 o=root 25965 25965 IN IP4 10.1.5.1 s=session c=IN IP4 10.1.5.1 t=0 0 m=audio 13110 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 21 08:47:57] DEBUG[25969]: channel.c:2760 set_format: Set channel SIP/103-b781ee20 to write format slin [Feb 21 08:47:57] DEBUG[25969]: channel.c:1910 ast_settimeout: Scheduling timer at 160 sample intervals [Feb 21 08:47:57] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'Wait' -- Executing [1566@from-sip:3] Wait("SIP/103-b781ee20", "5") in new stack [Feb 21 08:47:57] DEBUG[25969]: rtp.c:2792 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 21 08:47:57] DEBUG[25969]: rtp.c:2809 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 21 08:47:57] DEBUG[25969]: rtp.c:1220 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 10.1.10.11:16442 [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2245 __ast_read: Generator got voice, switching to phase locked mode [Feb 21 08:47:57] DEBUG[25969]: channel.c:1910 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:2160 __sip_autodestruct: Auto destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' [Feb 21 08:47:57] DEBUG[25969]: chan_sip.c:3400 sip_destroy: Destroying SIP dialog D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Really destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' Method: OPTIONS [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:57] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:58] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: chan_sip.c:2160 __sip_autodestruct: Auto destroying SIP dialog '84CA7AE1-137A-4ADA-8E7D-4672D470CFD0@192.168.4.11' [Feb 21 08:47:59] DEBUG[25969]: chan_sip.c:3400 sip_destroy: Destroying SIP dialog 84CA7AE1-137A-4ADA-8E7D-4672D470CFD0@192.168.4.11 Really destroying SIP dialog '84CA7AE1-137A-4ADA-8E7D-4672D470CFD0@192.168.4.11' Method: REGISTER [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:47:59] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:00] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:01] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'StopPlayTones' -- Executing [1566@from-sip:4] StopPlayTones("SIP/103-b781ee20", "") in new stack [Feb 21 08:48:02] DEBUG[25969]: channel.c:2760 set_format: Set channel SIP/103-b781ee20 to write format ulaw [Feb 21 08:48:02] DEBUG[25969]: channel.c:1910 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 21 08:48:02] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'Answer' -- Executing [1566@from-sip:5] Answer("SIP/103-b781ee20", "") in new stack [Feb 21 08:48:02] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-b781ee20 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:3753 sip_answer: SIP answering channel: SIP/103-b781ee20 [Feb 21 08:48:02] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:6936 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:02] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:48:02] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:6658 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:6660 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.1.5.1 port 13110 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:6821 add_sdp: -- Done with adding codecs to SDP [Feb 21 08:48:02] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:48:02] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:6881 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 10.1.10.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-fd0097a8;received=10.1.10.11 From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as30ec28d5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 232 v=0 o=root 25965 25966 IN IP4 10.1.5.1 s=session c=IN IP4 10.1.5.1 t=0 0 m=audio 13110 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #163 [Feb 21 08:48:02] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'Playback' -- Executing [1566@from-sip:6] Playback("SIP/103-b781ee20", "/var/lib/asterisk/moh/fpm-calm-river") in new stack [Feb 21 08:48:02] DEBUG[25969]: channel.c:2760 set_format: Set channel SIP/103-b781ee20 to write format slin [Feb 21 08:48:02] DEBUG[25969]: rtp.c:2809 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 21 08:48:02] DEBUG[25969]: channel.c:1910 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing '/var/lib/asterisk/moh/fpm-calm-river' (language 'de') <--- SIP read from 10.1.10.11:5060 ---> ACK sip:1566@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-da48a857 From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as30ec28d5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="103",realm="asterisk",nonce="068a1a58",uri="sip:1566@10.1.5.1",algorithm=MD5,response="aaedd59e7c8df7dc29e5b8c5c928f26f" Contact: "sip2" User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 29]: ACK sip:1566@10.1.5.1 SIP/2.0 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-da48a857 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 54]: From: "sip2" ;tag=532ae57e184bc26eo0 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 38]: To: ;tag=as30ec28d5 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 37]: Call-ID: 7f46aebe-88208a2e@172.24.0.2 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 13]: CSeq: 102 ACK [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [152]: Authorization: Digest username="103",realm="asterisk",nonce="068a1a58",uri="sip:1566@10.1.5.1",algorithm=MD5,response="aaedd59e7c8df7dc29e5b8c5c928f26f" [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 41]: Contact: "sip2" [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 7f46aebe-88208a2e@172.24.0.2 (Checking From) --From tag 532ae57e184bc26eo0 --To-tag as30ec28d5 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as30ec28d5 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #163 [Feb 21 08:48:02] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '7f46aebe-88208a2e@172.24.0.2' of Response 102: Match Found sip show inuse * User name In use Limit * Peer name In use Limit 103 1/0/0 2 102 0/0/0 2 101 0/0/0 2 *CLI> <--- SIP read from 192.168.170.244:5060 ---> OPTIONS sip:192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45dbf97e000034d600000103 Content-Length: 0 Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 CSeq: 72 OPTIONS From: ;tag=9028009325808 Max-Forwards: 70 To: <-------------> [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45dbf97e000034d600000103 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 72 OPTIONS [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: From: ;tag=9028009325808 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 29]: To: --- (8 headers 0 lines) --- [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 (Checking From) --From tag 9028009325808 --To-tag [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as30ec28d5 [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9026009332723 Our tag: as5a9e322b [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 - OPTIONS (No RTP) [Feb 21 08:48:05] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.168.35) <--- Transmitting (no NAT) to 192.168.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000000b45dbf97e000034d600000103;received=192.168.170.244;rport=5060 From: ;tag=9028009325808 To: ;tag=as589489b9 Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 CSeq: 72 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' in 32000 ms (Method: OPTIONS) sip show inuse * User name In use Limit * Peer name In use Limit 103 1/0/0 2 102 0/0/0 2 101 0/0/0 2 *CLI> <--- SIP read from 192.168.170.244:5060 ---> INVITE sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf98400007ad200000105 Content-Length: 343 Contact: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=9028659324160 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3381032964 3381032964 IN IP4 192.168.170.244 s=SJphone c=IN IP4 192.168.170.244 t=0 0 a=direction:active m=audio 49156 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf98400007ad200000105 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 19]: Content-Length: 343 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 39]: Contact: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 58]: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 14]: CSeq: 1 INVITE [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 62]: From: "unknown";tag=9028659324160 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 33]: To: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 0]: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 48]: o=- 3381032964 3381032964 IN IP4 192.168.170.244 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 9]: s=SJphone [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 18]: a=direction:active [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 37]: m=audio 49156 RTP/AVP 3 97 98 8 0 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 14 lines) --- [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 (Checking From) --From tag 9028659324160 --To-tag [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9028009325808 Our tag: as589489b9 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as30ec28d5 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9026009332723 Our tag: as5a9e322b [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to Off [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to Off [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to Off [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 - INVITE (With RTP) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:13959 handle_request_invite: Initializing initreq for method INVITE - callid 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Using INVITE request as basis request - 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.170.244:5060 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to On [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On <--- Reliably Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000005245dbf98400007ad200000105;received=192.168.170.244;rport=5060 From: "unknown";tag=9028659324160 To: ;tag=as001913a3 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="08e6b461" Content-Length: 0 <------------> [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #165 Scheduling destruction of SIP dialog '3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11' in 6848 ms (Method: INVITE) <--- SIP read from 192.168.170.244:5060 ---> ACK sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf98400007ad200000105 Content-Length: 0 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 1 ACK From: "unknown";tag=9028659324160 Max-Forwards: 70 To: ;tag=as001913a3 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: ACK sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf98400007ad200000105 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 62]: From: "unknown";tag=9028659324160 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 48]: To: ;tag=as001913a3 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 (Checking From) --From tag 9028659324160 --To-tag as001913a3 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Their Tag 9028659324160 Our tag: as001913a3 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #165 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11' of Response 1: Match Found <--- SIP read from 192.168.170.244:5060 ---> INVITE sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106 Content-Length: 343 Contact: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=9028659324160 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Authorization: Digest username="101",realm="asterisk",nonce="08e6b461",uri="sip:103@192.168.168.35:5060",response="d9e4fcdf34cd74107257113233f91959",algorithm="MD5" v=0 o=- 3381032964 3381032964 IN IP4 192.168.170.244 s=SJphone c=IN IP4 192.168.170.244 t=0 0 a=direction:active m=audio 49156 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 19]: Content-Length: 343 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 39]: Contact: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 58]: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 14]: CSeq: 2 INVITE [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 62]: From: "unknown";tag=9028659324160 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 33]: To: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [164]: Authorization: Digest username="101",realm="asterisk",nonce="08e6b461",uri="sip:103@192.168.168.35:5060",response="d9e4fcdf34cd74107257113233f91959",algorithm="MD5" [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 0]: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 48]: o=- 3381032964 3381032964 IN IP4 192.168.170.244 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 9]: s=SJphone [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 18]: a=direction:active [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 37]: m=audio 49156 RTP/AVP 3 97 98 8 0 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (12 headers 14 lines) --- [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 (Checking From) --From tag 9028659324160 --To-tag [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Their Tag 9028659324160 Our tag: as001913a3 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:13959 handle_request_invite: Initializing initreq for method INVITE - callid 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Using INVITE request as basis request - 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.170.244:5060 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2846 do_setnat: Setting NAT on VRTP to On [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On Found RTP audio format 3 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:5266 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.170.244:49156 Found description format GSM for ID 3 Found description format iLBC for ID 97 Found description format iLBC for ID 98 Got unsupported a:fmtp in SDP offer Found description format PCMA for ID 8 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:5508 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x4 (ulaw), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.170.244:49156 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:5599 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:14040 handle_request_invite: Checking SIP call limits for device 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for incoming call [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:3374 update_call_counter: Call from peer '101' is 1 out of 2 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 Looking for 103 in from-sip (domain 192.168.168.35) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4118 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4119 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4120 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4121 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4151 sip_new: This channel will not be able to handle video. [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:8462 build_route: build_route: Contact hop: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 list_route: hop: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:14115 handle_request_invite: SIP/101-081c5198: New call is still down.... Trying... <--- Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106;received=192.168.170.244;rport=5060 From: "unknown";tag=9028659324160 To: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081c5198 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:12] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'INUSE' [Feb 21 08:48:12] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 -- Executing [103@from-sip:1] NoOp("SIP/101-081c5198", "SIP/103 has state INUSE") in new stack [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:12] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1' [Feb 21 08:48:12] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:48:12] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:2] NoOp("SIP/101-081c5198", "SIPPEER(103:curcalls) is 1") in new stack [Feb 21 08:48:12] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:48:12] DEBUG[25969]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [103@from-sip:3] Dial("SIP/101-081c5198", "SIP/103") in new stack [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15950 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2896 create_addr_from_peer: Our T38 capability (3856) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2841 do_setnat: Setting NAT on RTP to On [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2851 do_setnat: Setting NAT on UDPTL to On [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:1782 obproxy_get: OBPROXY: Not applying OBproxy to this call [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4118 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4119 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4120 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4121 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4123 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4151 sip_new: This channel will not be able to handle video. [Feb 21 08:48:12] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-3. [Feb 21 08:48:12] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-2. [Feb 21 08:48:12] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-1. [Feb 21 08:48:12] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 21 08:48:12] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 21 08:48:12] DEBUG[25969]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:3121 sip_call: Outgoing Call for 103 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for outgoing call [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:3374 update_call_counter: Call to peer '103' is 2 out of 2 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:3139 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 7 (Ring+Inuse) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:6658 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:6660 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.5.1 port 12488 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:12] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue. Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:6821 add_sdp: -- Done with adding codecs to SDP [Feb 21 08:48:12] DEBUG[25969]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=32) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:6881 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:1717 initialize_initreq: Initializing initreq for method INVITE - callid 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 38]: INVITE sip:103@172.24.0.2:5060 SIP/2.0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 59]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608;rport [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 49]: From: "unknown" ;tag=as5b55b539 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 29]: To: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 27]: Contact: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 50]: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r55495 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 35]: Date: Wed, 21 Feb 2007 07:48:12 GMT [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 19]: Supported: replaces [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 13 [ 19]: Content-Length: 232 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 14 [ 0]: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 0 [ 3]: v=0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 1 [ 34]: o=root 25965 25965 IN IP4 10.1.5.1 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 2 [ 9]: s=session [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 3 [ 17]: c=IN IP4 10.1.5.1 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 4 [ 5]: t=0 0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 5 [ 27]: m=audio 12488 RTP/AVP 0 101 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (NAT) to 10.1.10.11:5060: INVITE sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608;rport Max-Forwards: 70 From: "unknown" ;tag=as5b55b539 To: Contact: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Date: Wed, 21 Feb 2007 07:48:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 232 v=0 o=root 25965 25965 IN IP4 10.1.5.1 s=session c=IN IP4 10.1.5.1 t=0 0 m=audio 12488 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #167 -- Called 103 <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 100 Trying To: From: "unknown" ;tag=as5b55b539 Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 29]: To: [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as5b55b539 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 (Checking To) --From tag as5b55b539 --To-tag [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag Our tag: as5b55b539 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2267 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #167 - INVITE (got response) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2276 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' Request 102: Found [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:12271 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 180 Ringing To: ;tag=196cbb367c12de3i0 From: "unknown" ;tag=as5b55b539 Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 51]: To: ;tag=196cbb367c12de3i0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as5b55b539 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 (Checking To) --From tag as5b55b539 --To-tag 196cbb367c12de3i0 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag Our tag: as5b55b539 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:2276 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' Request 102: Found [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:12271 handle_response_invite: SIP response 180 to standard invite [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081c94f8 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 7 (Ring+Inuse) [Feb 21 08:48:12] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:12] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:12] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue. -- SIP/103-081c94f8 is ringing <--- Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106;received=192.168.170.244;rport=5060 From: "unknown";tag=9028659324160 To: ;tag=as3a60e6d8 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> sip show inuse * User name In use Limit * Peer name In use Limit 103 2/1/0 2 102 0/0/0 2 101 1/0/0 2 *CLI> [Feb 21 08:48:17] DEBUG[25969]: chan_sip.c:2160 __sip_autodestruct: Auto destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' [Feb 21 08:48:17] DEBUG[25969]: chan_sip.c:3400 sip_destroy: Destroying SIP dialog D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Really destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' Method: OPTIONS <--- SIP read from 192.168.170.244:5060 ---> CANCEL sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106 Content-Length: 0 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 2 CANCEL From: "unknown";tag=9028659324160 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 42]: CANCEL sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 14]: CSeq: 2 CANCEL [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 62]: From: "unknown";tag=9028659324160 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 33]: To: [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 (Checking From) --From tag 9028659324160 --To-tag [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag 196cbb367c12de3i0 Our tag: as5b55b539 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Their Tag 9028659324160 Our tag: as3a60e6d8 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL Sending to 192.168.170.244 : 5060 (NAT) [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:1730 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 <--- Reliably Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106;received=192.168.170.244;rport=5060 From: "unknown";tag=9028659324160 To: ;tag=as3a60e6d8 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #169 <--- Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106;received=192.168.170.244;rport=5060 From: "unknown";tag=9028659324160 To: ;tag=as3a60e6d8 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 2 CANCEL User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:48:19] DEBUG[25969]: rtp.c:1566 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 21 08:48:19] DEBUG[25969]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/103-081c94f8' [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3597 sip_hangup: Hangup call SIP/103-081c94f8, SIP callid 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1) [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3605 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for outgoing call [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3348 update_call_counter: Call to peer '103' removed from call limit 2 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3619 sip_hangup: Hanging up channel in state Ringing (not UP) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 Scheduling destruction of SIP dialog '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' in 6400 ms (Method: INVITE) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2217 __sip_ack: Acked pending invite 102 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:19] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' of Request 102: Match Found Reliably Transmitting (NAT) to 10.1.10.11:5060: CANCEL sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608;rport Max-Forwards: 70 From: "unknown" ;tag=as5b55b539 To: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 CANCEL User-Agent: Asterisk PBX SVN-trunk-r55495 Content-Length: 0 --- [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #171 Scheduling destruction of SIP dialog '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' in 6400 ms (Method: INVITE) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081c94f8 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:19] DEBUG[25969]: app_dial.c:1710 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:48:19] DEBUG[25969]: pbx.c:2289 __ast_pbx_run: Spawn extension (from-sip,103,3) exited non-zero on 'SIP/101-081c5198' [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:19] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. == Spawn extension (from-sip, 103, 3) exited non-zero on 'SIP/101-081c5198' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"unknown" <101>' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '101' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '103' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081c5198' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103-081c94f8' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-21 08:48:12' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-21 08:48:19' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '7' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '0' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1172044092.3' [Feb 21 08:48:19] DEBUG[25969]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 08:48:19] DEBUG[25969]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/101-081c5198' [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3597 sip_hangup: Hangup call SIP/101-081c5198, SIP callid 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11) [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3605 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for incoming call [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3348 update_call_counter: Call from peer '101' removed from call limit 2 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081c5198 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 101 [Feb 21 08:48:19] DEBUG[25969]: 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. [Feb 21 08:48:19] DEBUG[25969]: 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.170.244:5060 ---> ACK sip:103@192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106 Content-Length: 0 Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=9028659324160 Max-Forwards: 70 To: ;tag=as3a60e6d8 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: ACK sip:103@192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000005245dbf9840000786500000106 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 62]: From: "unknown";tag=9028659324160 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 48]: To: ;tag=as3a60e6d8 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 (Checking From) --From tag 9028659324160 --To-tag as3a60e6d8 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag 196cbb367c12de3i0 Our tag: as5b55b539 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11 Their Tag 9028659324160 Our tag: as3a60e6d8 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #169 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11' of Response 2: Match Found Really destroying SIP dialog '3DEF8EC5-4C6C-4CAC-9488-E733124DD494@192.168.4.11' Method: ACK <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 487 Request Terminated To: ;tag=196cbb367c12de3i0 From: "unknown" ;tag=as5b55b539 Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 30]: SIP/2.0 487 Request Terminated [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 51]: To: ;tag=196cbb367c12de3i0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as5b55b539 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 (Checking To) --From tag as5b55b539 --To-tag 196cbb367c12de3i0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag 196cbb367c12de3i0 Our tag: as5b55b539 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' of Request 102: Match Not Found [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:12271 handle_response_invite: SIP response 487 to standard invite Transmitting (NAT) to 10.1.10.11:5060: ACK sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608;rport Max-Forwards: 70 From: "unknown" ;tag=as5b55b539 To: ;tag=196cbb367c12de3i0 Contact: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r55495 Content-Length: 0 --- [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for outgoing call [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:3348 update_call_counter: Call to peer '103' removed from call limit 2 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Feb 21 08:48:19] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:19] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 200 OK To: ;tag=196cbb367c12de3i0 From: "unknown" ;tag=as5b55b539 Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 CSeq: 102 CANCEL Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 51]: To: ;tag=196cbb367c12de3i0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as5b55b539 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 102 CANCEL [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK5f948608 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 (Checking To) --From tag as5b55b539 --To-tag 196cbb367c12de3i0 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag 196cbb367c12de3i0 Our tag: as5b55b539 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #171 [Feb 21 08:48:19] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' of Request 102: Match Found sip show inuse * User name In use Limit * Peer name In use Limit 103 0/0/0 2 102 0/0/0 2 101 0/0/0 2 *CLI> [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:1717 initialize_initreq: Initializing initreq for method OPTIONS - callid 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: OPTIONS sip:103@172.24.0.2:5060 SIP/2.0 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 59]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK6fa862d4;rport [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 55]: From: "asterisk" ;tag=as00517a96 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 29]: To: [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 32]: Contact: [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 50]: Call-ID: 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r55495 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 35]: Date: Wed, 21 Feb 2007 07:48:24 GMT [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 19]: Supported: replaces [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 17]: Content-Length: 0 Reliably Transmitting (NAT) to 10.1.10.11:5060: OPTIONS sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK6fa862d4;rport Max-Forwards: 70 From: "asterisk" ;tag=as00517a96 To: Contact: Call-ID: 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r55495 Date: Wed, 21 Feb 2007 07:48:24 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #173 <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 200 OK To: ;tag=bebb151753e7caa0i0 From: "asterisk" ;tag=as00517a96 Call-ID: 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 CSeq: 102 OPTIONS Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK6fa862d4 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER <-------------> [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 52]: To: ;tag=bebb151753e7caa0i0 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 55]: From: "asterisk" ;tag=as00517a96 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 50]: Call-ID: 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 17]: CSeq: 102 OPTIONS [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK6fa862d4 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: Content-Length: 0 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER --- (9 headers 0 lines) --- [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 (Checking To) --From tag as00517a96 --To-tag bebb151753e7caa0i0 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 6f11fcc76350486d1ca14a48439680fb@10.1.5.1 Their Tag Our tag: as00517a96 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #173 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '6f11fcc76350486d1ca14a48439680fb@10.1.5.1' of Request 102: Match Found Really destroying SIP dialog '6f11fcc76350486d1ca14a48439680fb@10.1.5.1' Method: OPTIONS [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:1717 initialize_initreq: Initializing initreq for method OPTIONS - callid 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 44]: OPTIONS sip:101@192.168.170.244:5060 SIP/2.0 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.168.35:5060;branch=z9hG4bK4a6e6f58;rport [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as28455a87 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 34]: To: [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 38]: Contact: [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 56]: Call-ID: 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r55495 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 35]: Date: Wed, 21 Feb 2007 07:48:24 GMT [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 11 [ 19]: Supported: replaces [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 12 [ 17]: Content-Length: 0 Reliably Transmitting (NAT) to 192.168.170.244:5060: OPTIONS sip:101@192.168.170.244:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.168.35:5060;branch=z9hG4bK4a6e6f58;rport Max-Forwards: 70 From: "asterisk" ;tag=as28455a87 To: Contact: Call-ID: 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r55495 Date: Wed, 21 Feb 2007 07:48:24 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:2114 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #176 <--- SIP read from 192.168.170.244:5060 ---> SIP/2.0 405 Method Not Allowed Via: SIP/2.0/UDP 192.168.168.35:5060;rport=5060;received=192.168.168.35;branch=z9hG4bK4a6e6f58 Content-Length: 0 Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY Call-ID: 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 CSeq: 102 OPTIONS From: "asterisk";tag=as28455a87 Server: SJphone/1.60.289a (SJ Labs) To: "unknown" <-------------> [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 30]: SIP/2.0 405 Method Not Allowed [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 192.168.168.35:5060;rport=5060;received=192.168.168.35;branch=z9hG4bK4a6e6f58 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 46]: Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 56]: Call-ID: 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 60]: From: "asterisk";tag=as28455a87 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 35]: Server: SJphone/1.60.289a (SJ Labs) [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 43]: To: "unknown" --- (9 headers 0 lines) --- [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 (Checking To) --From tag as28455a87 --To-tag [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 3bd2397e2527403a012a8b374b7f9ada@192.168.168.35 Their Tag Our tag: as28455a87 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:2222 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #176 [Feb 21 08:48:24] DEBUG[25969]: chan_sip.c:2233 __sip_ack: Stopping retransmission on '3bd2397e2527403a012a8b374b7f9ada@192.168.168.35' of Request 102: Match Found Really destroying SIP dialog '3bd2397e2527403a012a8b374b7f9ada@192.168.168.35' Method: OPTIONS <--- SIP read from 192.168.170.244:5060 ---> OPTIONS sip:192.168.168.35:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45dbf992000029eb0000010c Content-Length: 0 Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 CSeq: 73 OPTIONS From: ;tag=90300093614 Max-Forwards: 70 To: <-------------> [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45dbf992000029eb0000010c [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 58]: Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 16]: CSeq: 73 OPTIONS [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 51]: From: ;tag=90300093614 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [ 29]: To: --- (8 headers 0 lines) --- [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 (Checking From) --From tag 90300093614 --To-tag [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Their Tag 196cbb367c12de3i0 Our tag: as5b55b539 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9028009325808 Our tag: as589489b9 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as30ec28d5 [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:4647 sip_alloc: Allocating new SIP dialog for D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 - OPTIONS (No RTP) [Feb 21 08:48:25] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.168.35) <--- Transmitting (no NAT) to 192.168.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000000b45dbf992000029eb0000010c;received=192.168.170.244;rport=5060 From: ;tag=90300093614 To: ;tag=as69516757 Call-ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 CSeq: 73 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' in 32000 ms (Method: OPTIONS) [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:2160 __sip_autodestruct: Auto destroying SIP dialog '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:3400 sip_destroy: Destroying SIP dialog 25293d14448f3d2d4e4adf94323e2dac@10.1.5.1 Really destroying SIP dialog '25293d14448f3d2d4e4adf94323e2dac@10.1.5.1' Method: INVITE <--- SIP read from 10.1.10.11:5060 ---> BYE sip:1566@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-bf3cf550 From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as30ec28d5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 103 BYE Max-Forwards: 70 Authorization: Digest username="103",realm="asterisk",nonce="068a1a58",uri="sip:1566@10.1.5.1",algorithm=MD5,response="e663e96052fca9118763cfc94248b42c" User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 0 [ 29]: BYE sip:1566@10.1.5.1 SIP/2.0 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-bf3cf550 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 2 [ 54]: From: "sip2" ;tag=532ae57e184bc26eo0 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 3 [ 38]: To: ;tag=as30ec28d5 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 4 [ 37]: Call-ID: 7f46aebe-88208a2e@172.24.0.2 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 5 [ 13]: CSeq: 103 BYE [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 7 [152]: Authorization: Digest username="103",realm="asterisk",nonce="068a1a58",uri="sip:1566@10.1.5.1",algorithm=MD5,response="e663e96052fca9118763cfc94248b42c" [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 8 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4925 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4684 find_call: = Looking for Call ID: 7f46aebe-88208a2e@172.24.0.2 (Checking From) --From tag 532ae57e184bc26eo0 --To-tag as30ec28d5 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 90300093614 Our tag: as69516757 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4711 find_call: = No match Their Call ID: D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Their Tag 9028009325808 Our tag: as589489b9 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:4711 find_call: = Found Their Call ID: 7f46aebe-88208a2e@172.24.0.2 Their Tag 532ae57e184bc26eo0 Our tag: as30ec28d5 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:15255 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:14781 handle_request_bye: Initializing initreq for method BYE - callid 7f46aebe-88208a2e@172.24.0.2 Sending to 10.1.10.11 : 5060 (NAT) [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:1730 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7f46aebe-88208a2e@172.24.0.2 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:14838 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 10.1.10.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-bf3cf550;received=10.1.10.11 From: "sip2" ;tag=532ae57e184bc26eo0 To: ;tag=as30ec28d5 Call-ID: 7f46aebe-88208a2e@172.24.0.2 CSeq: 103 BYE User-Agent: Asterisk PBX SVN-trunk-r55495 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 08:48:26] DEBUG[25969]: channel.c:1910 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 21 08:48:26] DEBUG[25969]: channel.c:2760 set_format: Set channel SIP/103-b781ee20 to write format ulaw [Feb 21 08:48:26] DEBUG[25969]: pbx.c:2289 __ast_pbx_run: Spawn extension (from-sip,1566,6) exited non-zero on 'SIP/103-b781ee20' == Spawn extension (from-sip, 1566, 6) exited non-zero on 'SIP/103-b781ee20' [Feb 21 08:48:26] DEBUG[25969]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/103-b781ee20' [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:3597 sip_hangup: Hangup call SIP/103-b781ee20, SIP callid 7f46aebe-88208a2e@172.24.0.2) [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:3605 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:3304 update_call_counter: Updating call counter for incoming call [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:3348 update_call_counter: Call from peer '103' removed from call limit 2 [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-b781ee20 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 21 08:48:26] DEBUG[25969]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 21 08:48:26] DEBUG[25969]: chan_sip.c:15881 sip_devicestate: Checking device state for peer 103 [Feb 21 08:48:26] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 21 08:48:26] DEBUG[25969]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. Really destroying SIP dialog '7f46aebe-88208a2e@172.24.0.2' Method: BYE sip show inuse * User name In use Limit * Peer name In use Limit 103 -1/0/0 2 102 0/0/0 2 101 0/0/0 2 *CLI> core show hints -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:InUse Watchers 0 102@from-sip : SIP/102 State:Unavailable Watchers 0 101@from-sip : SIP/101 State:Idle Watchers 0 ---------------- - 3 hints registered *CLI> [Feb 21 08:48:37] DEBUG[25969]: chan_sip.c:2160 __sip_autodestruct: Auto destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' [Feb 21 08:48:37] DEBUG[25969]: chan_sip.c:3400 sip_destroy: Destroying SIP dialog D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11 Really destroying SIP dialog 'D2E31EFD-0282-4A4D-BBC9-6C82564EFACC@192.168.4.11' Method: OPTIONS core show version Asterisk SVN-trunk-r55495 built by root @ asterisktest on a i686 running Linux on 2007-02-20 07:00:08 UTC *CLI> stop now Beginning asterisk shutdown.... Executing last minute cleanups == Destroying musiconhold processes Asterisk cleanly ending (0). [Feb 21 08:48:44] DEBUG[25969]: asterisk.c:1229 quit_handler: Asterisk ending (0).