[*CLI> core set debug atleast 5 Core debug is at least 5 [*CLI> sip set debug 5 SIP Debugging enabled *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=z9hG4bKc0a8040b0000001045ddc1860000390f00000012 Content-Length: 0 Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 CSeq: 2 OPTIONS From: ;tag=3383757831617 Max-Forwards: 70 To: <-------------> [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0 [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000001045ddc1860000390f00000012 [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 15]: CSeq: 2 OPTIONS [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: From: ;tag=3383757831617 [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 29]: To: --- (8 headers 0 lines) --- [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 (Checking From) --From tag 3383757831617 --To-tag [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 - OPTIONS (No RTP) [Feb 22 17:15:02] DEBUG[16983]: chan_sip.c:15271 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=z9hG4bKc0a8040b0000001045ddc1860000390f00000012;received=192.168.170.244;rport=5060 From: ;tag=3383757831617 To: ;tag=as354b04cb Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 CSeq: 2 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' in 32000 ms (Method: OPTIONS) sip show peers Name/username Host Dyn Nat ACL Port Status 103/103 10.1.10.11 D N 5060 OK (24 ms) 102 (Unspecified) D N 0 UNKNOWN 101/101 192.168.170.244 D N 5060 OK (28 ms) 3 sip peers [Monitored: 2 online, 1 offline Unmonitored: 0 online, 0 offline] *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=z9hG4bKc0a8040b0000002045ddc19000004c4900000014 Content-Length: 343 Contact: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=3384804610551 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3381149712 3381149712 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 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19000004c4900000014 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 19]: Content-Length: 343 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 39]: Contact: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 14]: CSeq: 1 INVITE [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 33]: To: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 0]: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 48]: o=- 3381149712 3381149712 IN IP4 192.168.170.244 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=SJphone [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 18]: a=direction:active [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 37]: m=audio 49154 RTP/AVP 3 97 98 8 0 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 14 lines) --- [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3383757831617 Our tag: as354b04cb [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2847 do_setnat: Setting NAT on VRTP to Off [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2852 do_setnat: Setting NAT on UDPTL to Off [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 - INVITE (With RTP) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Using INVITE request as basis request - 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.170.244:5060 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to On [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2847 do_setnat: Setting NAT on VRTP to On [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2852 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=z9hG4bKc0a8040b0000002045ddc19000004c4900000014;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: ;tag=as17a71a31 Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="78f4082b" Content-Length: 0 <------------> [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #15 Scheduling destruction of SIP dialog '1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11' in 1792 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=z9hG4bKc0a8040b0000002045ddc19000004c4900000014 Content-Length: 0 Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 1 ACK From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as17a71a31 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 39]: ACK sip:103@192.168.168.35:5060 SIP/2.0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19000004c4900000014 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 48]: To: ;tag=as17a71a31 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as17a71a31 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as17a71a31 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '1757D124-E379-4479-80A2-62090E4C3760@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=z9hG4bKc0a8040b0000002045ddc190000048e900000015 Content-Length: 343 Contact: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=3384804610551 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Authorization: Digest username="101",realm="asterisk",nonce="78f4082b",uri="sip:103@192.168.168.35:5060",response="cf81116355e3cd952b5601b5e54629f2",algorithm="MD5" v=0 o=- 3381149712 3381149712 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 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc190000048e900000015 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 19]: Content-Length: 343 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 39]: Contact: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 14]: CSeq: 2 INVITE [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 33]: To: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [164]: Authorization: Digest username="101",realm="asterisk",nonce="78f4082b",uri="sip:103@192.168.168.35:5060",response="cf81116355e3cd952b5601b5e54629f2",algorithm="MD5" [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 12 [ 0]: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 48]: o=- 3381149712 3381149712 IN IP4 192.168.170.244 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=SJphone [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 18]: a=direction:active [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 37]: m=audio 49154 RTP/AVP 3 97 98 8 0 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (12 headers 14 lines) --- [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as17a71a31 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Using INVITE request as basis request - 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.170.244:5060 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to On [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2847 do_setnat: Setting NAT on VRTP to On [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2852 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 22 17:15:13] DEBUG[16983]: chan_sip.c:5282 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 22 17:15:13] DEBUG[16983]: chan_sip.c:5524 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 22 17:15:13] DEBUG[16983]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:14056 handle_request_invite: Checking SIP call limits for device 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:3375 update_call_counter: Call from peer '101' is 1 out of 2 [Feb 22 17:15:13] DEBUG[16983]: 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 22 17:15:13] DEBUG[16983]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4128 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4159 sip_new: This channel will not be able to handle video. [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:8478 build_route: build_route: Contact hop: list_route: hop: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:14131 handle_request_invite: SIP/101-081c6850: 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=z9hG4bKc0a8040b0000002045ddc190000048e900000015;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081c6850 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:13] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'NOT_INUSE' [Feb 22 17:15:13] DEBUG[16983]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:1] NoOp("SIP/101-081c6850", "SIP/103 has state NOT_INUSE") in new stack [Feb 22 17:15:13] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '0' [Feb 22 17:15:13] DEBUG[16983]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:2] NoOp("SIP/101-081c6850", "SIPPEER(103:curcalls) is 0") in new stack [Feb 22 17:15:13] DEBUG[16983]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [103@from-sip:3] Dial("SIP/101-081c6850", "SIP/103") in new stack [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15966 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2897 create_addr_from_peer: Our T38 capability (3856) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to On [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2852 do_setnat: Setting NAT on UDPTL to On [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:1783 obproxy_get: OBPROXY: Not applying OBproxy to this call [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4128 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4131 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4159 sip_new: This channel will not be able to handle video. [Feb 22 17:15:13] DEBUG[16983]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-3. [Feb 22 17:15:13] DEBUG[16983]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-2. [Feb 22 17:15:13] DEBUG[16983]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-1. [Feb 22 17:15:13] DEBUG[16983]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 22 17:15:13] DEBUG[16983]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 22 17:15:13] DEBUG[16983]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:3122 sip_call: Outgoing Call for 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:3375 update_call_counter: Call to peer '103' is 1 out of 2 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:3140 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.5.1 port 19044 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 22 17:15:13] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method INVITE - callid 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 38]: INVITE sip:103@172.24.0.2:5060 SIP/2.0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 59]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d;rport [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 49]: From: "unknown" ;tag=as1b771f01 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 29]: To: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 27]: Contact: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56095 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 35]: Date: Thu, 22 Feb 2007 16:15:13 GMT [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 19]: Supported: replaces [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 232 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 34]: o=root 16979 16979 IN IP4 10.1.5.1 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 17]: c=IN IP4 10.1.5.1 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 19044 RTP/AVP 0 101 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 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=z9hG4bK68c4117d;rport Max-Forwards: 70 From: "unknown" ;tag=as1b771f01 To: Contact: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Date: Thu, 22 Feb 2007 16:15:13 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 232 v=0 o=root 16979 16979 IN IP4 10.1.5.1 s=session c=IN IP4 10.1.5.1 t=0 0 m=audio 19044 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 22 17:15:13] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #17 -- Called 103 [Feb 22 17:15:13] DEBUG[16983]: 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 22 17:15:13] DEBUG[16983]: 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 22 17:15:13] DEBUG[16983]: 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 read from 10.1.10.11:5060 ---> SIP/2.0 100 Trying To: From: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 29]: To: [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as1b771f01 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 (Checking To) --From tag as1b771f01 --To-tag [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag Our tag: as1b771f01 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2268 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #17 - INVITE (got response) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' Request 102: Found [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:12287 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 180 Ringing To: ;tag=cd6102ad90f7604ci0 From: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 52]: To: ;tag=cd6102ad90f7604ci0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as1b771f01 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 (Checking To) --From tag as1b771f01 --To-tag cd6102ad90f7604ci0 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag Our tag: as1b771f01 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' Request 102: Found [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:12287 handle_response_invite: SIP response 180 to standard invite [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-b790c580 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Feb 22 17:15:13] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:13] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 -- SIP/103-b790c580 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=z9hG4bKc0a8040b0000002045ddc190000048e900000015;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: ;tag=as3569f33c Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 22 17:15:13] DEBUG[16983]: 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 read from 10.1.10.11:5060 ---> SIP/2.0 200 OK To: ;tag=cd6102ad90f7604ci0 From: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d Contact: "sip2" Server: Linksys/SPA901-4.1.11(c) Content-Length: 206 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 20551830 20551830 IN IP4 172.24.0.2 s=- c=IN IP4 172.24.0.2 t=0 0 m=audio 16452 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 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 52]: To: ;tag=cd6102ad90f7604ci0 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as1b771f01 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK68c4117d [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 41]: Contact: "sip2" [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Content-Length: 206 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 0]: [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 39]: o=- 20551830 20551830 IN IP4 172.24.0.2 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 3]: s=- [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 19]: c=IN IP4 172.24.0.2 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 16452 RTP/AVP 0 101 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 9 [ 10]: a=ptime:30 --- (11 headers 10 lines) --- [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 (Checking To) --From tag as1b771f01 --To-tag cd6102ad90f7604ci0 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:2218 __sip_ack: Acked pending invite 102 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' of Request 102: Match Found [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:12287 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:5282 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 172.24.0.2:16452 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/103-b790c580 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:16452 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:8478 build_route: build_route: Contact hop: "sip2" list_route: hop: [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:6050 reqprep: Strict routing enforced for session 7ebae5e826bc6afe16ec84df02e18477@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=z9hG4bK787be9c1;rport Max-Forwards: 70 From: "unknown" ;tag=as1b771f01 To: ;tag=cd6102ad90f7604ci0 Contact: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r56095 Content-Length: 0 --- [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 -- Call on SIP/103-b790c580 left from hold [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-b790c580 [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 -- SIP/103-b790c580 answered SIP/101-081c6850 [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081c6850 [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 22 17:15:17] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:3761 sip_answer: SIP answering channel: SIP/101-081c6850 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:6952 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.168.35 port 18254 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 22 17:15:17] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:6897 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=z9hG4bKc0a8040b0000002045ddc190000048e900000015;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: ;tag=as3569f33c Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 16979 16979 IN IP4 192.168.168.35 s=session c=IN IP4 192.168.168.35 t=0 0 m=audio 18254 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 22 17:15:17] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #19 [Feb 22 17:15:17] DEBUG[16983]: 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 22 17:15:17] DEBUG[16983]: 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 22 17:15:17] DEBUG[16983]: 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. <--- 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=z9hG4bKc0a8040b0000002045ddc194000071b500000019 Content-Length: 0 Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as3569f33c User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc194000071b500000019 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 48]: To: ;tag=as3569f33c [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as3569f33c [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #19 [Feb 22 17:15:17] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11' of Response 2: Match Found -- Packet2Packet bridging SIP/101-081c6850 and SIP/103-b790c580 [Feb 22 17:15:17] DEBUG[16983]: rtp.c:1220 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 10.1.10.11:16452 <--- SIP read from 192.168.170.244:5060 ---> INVITE sip:103@192.168.168.35 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19700006ab80000001a Content-Length: 217 Contact: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Content-Type: application/sdp CSeq: 3 INVITE From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as3569f33c User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3381149712 3381149713 IN IP4 192.168.170.244 s=SJphone c=IN IP4 0.0.0.0 t=0 0 a=direction:active m=audio 49154 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 37]: INVITE sip:103@192.168.168.35 SIP/2.0 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19700006ab80000001a [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 19]: Content-Length: 217 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 39]: Contact: [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 14]: CSeq: 3 INVITE [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 48]: To: ;tag=as3569f33c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 0]: [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 48]: o=- 3381149712 3381149713 IN IP4 192.168.170.244 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=SJphone [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 16]: c=IN IP4 0.0.0.0 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 18]: a=direction:active [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 27]: m=audio 49154 RTP/AVP 0 101 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 9 lines) --- [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as3569f33c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Found RTP audio format 0 Found RTP audio format 101 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:5282 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 0.0.0.0:49154 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/101-081c6850 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 0.0.0.0:49154 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 22 17:15:20] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:14109 handle_request_invite: Got a SIP re-invite for call 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:14204 handle_request_invite: SIP/101-081c6850: This call is UP.... [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:6952 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.168.35 port 18254 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:6897 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=z9hG4bKc0a8040b0000002045ddc19700006ab80000001a;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: ;tag=as3569f33c Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 3 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 16979 16980 IN IP4 192.168.168.35 s=session c=IN IP4 192.168.168.35 t=0 0 m=audio 18254 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 22 17:15:20] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #20 -- Started music on hold, class 'default', on SIP/103-b790c580 [Feb 22 17:15:20] DEBUG[16983]: channel.c:1910 ast_settimeout: Scheduling timer at 160 sample intervals [Feb 22 17:15:20] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:20] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Feb 22 17:15:20] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:20] DEBUG[16983]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2245 __ast_read: Generator got voice, switching to phase locked mode [Feb 22 17:15:20] DEBUG[16983]: channel.c:1910 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 22 17:15:20] DEBUG[16983]: channel.c:2760 set_format: Set channel SIP/103-b790c580 to write format slin [Feb 22 17:15:20] DEBUG[16983]: res_musiconhold.c:252 ast_moh_files_next: SIP/103-b790c580 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine' [Feb 22 17:15:20] DEBUG[16983]: rtp.c:2792 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 22 17:15:20] DEBUG[16983]: rtp.c:2809 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 <--- 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=z9hG4bKc0a8040b0000002045ddc197000077250000001c Content-Length: 0 Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 3 ACK From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as3569f33c User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc197000077250000001c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 3 ACK [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 48]: To: ;tag=as3569f33c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as3569f33c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #20 [Feb 22 17:15:20] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11' of Response 3: Match Found [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:20] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:21] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) <--- 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=z9hG4bKc0a8040b0000001045ddc19a00002a1c0000001d Content-Length: 0 Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 CSeq: 3 OPTIONS From: ;tag=3385757813933 Max-Forwards: 70 To: <-------------> [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0 [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000001045ddc19a00002a1c0000001d [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 15]: CSeq: 3 OPTIONS [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: From: ;tag=3385757813933 [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 29]: To: --- (8 headers 0 lines) --- [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 (Checking From) --From tag 3385757813933 --To-tag [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3383757831617 Our tag: as354b04cb [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 - OPTIONS (No RTP) [Feb 22 17:15:22] DEBUG[16983]: chan_sip.c:15271 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=z9hG4bKc0a8040b0000001045ddc19a00002a1c0000001d;received=192.168.170.244;rport=5060 From: ;tag=3385757813933 To: ;tag=as5c949e5d Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 CSeq: 3 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' in 32000 ms (Method: OPTIONS) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:22] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:23] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:24] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:25] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) <--- SIP read from 192.168.170.244:5060 ---> INVITE sip:103@192.168.168.35 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19d00005ced0000001f Content-Length: 225 Contact: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Content-Type: application/sdp CSeq: 4 INVITE From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as3569f33c User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3381149712 3381149714 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 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 37]: INVITE sip:103@192.168.168.35 SIP/2.0 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19d00005ced0000001f [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 19]: Content-Length: 225 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 39]: Contact: [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 14]: CSeq: 4 INVITE [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 48]: To: ;tag=as3569f33c [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 0]: [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 48]: o=- 3381149712 3381149714 IN IP4 192.168.170.244 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=SJphone [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 24]: c=IN IP4 192.168.170.244 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 18]: a=direction:active [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 27]: m=audio 49154 RTP/AVP 0 101 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 9 lines) --- [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as3569f33c [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.170.244 : 5060 (NAT) [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Found RTP audio format 0 Found RTP audio format 101 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:5282 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.170.244:49154 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/101-081c6850 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 192.168.170.244:49154 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:14109 handle_request_invite: Got a SIP re-invite for call 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:14204 handle_request_invite: SIP/101-081c6850: This call is UP.... [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:6952 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.168.35 port 18254 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 22 17:15:26] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:6897 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=z9hG4bKc0a8040b0000002045ddc19d00005ced0000001f;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: ;tag=as3569f33c Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 4 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 16979 16981 IN IP4 192.168.168.35 s=session c=IN IP4 192.168.168.35 t=0 0 m=audio 18254 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 22 17:15:26] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #23 -- Stopped music on hold on SIP/103-b790c580 [Feb 22 17:15:26] DEBUG[16983]: channel.c:2760 set_format: Set channel SIP/103-b790c580 to write format ulaw [Feb 22 17:15:26] DEBUG[16983]: channel.c:1910 ast_settimeout: Scheduling timer at 0 sample intervals <--- 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=z9hG4bKc0a8040b0000002045ddc19d0000738f00000021 Content-Length: 0 Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 4 ACK From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as3569f33c User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc19d0000738f00000021 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 4 ACK [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 48]: To: ;tag=as3569f33c [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as3569f33c [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #23 [Feb 22 17:15:26] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11' of Response 4: Match Found <--- SIP read from 10.1.10.11:5060 ---> INVITE sip:101@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-cc55a5e1 From: ;tag=cd6102ad90f7604ci0 To: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 101 INVITE Max-Forwards: 70 Contact: "sip2" Expires: 30 User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 203 Content-Type: application/sdp v=0 o=- 20553410 20553410 IN IP4 172.24.0.2 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16452 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendonly <-------------> [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 31]: INVITE sip:101@10.1.5.1 SIP/2.0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-cc55a5e1 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 54]: From: ;tag=cd6102ad90f7604ci0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 47]: To: "unknown" ;tag=as1b771f01 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 16]: CSeq: 101 INVITE [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 41]: Contact: "sip2" [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 11]: Expires: 30 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Content-Length: 203 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 12 [ 0]: [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 1 [ 39]: o=- 20553410 20553410 IN IP4 172.24.0.2 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 2 [ 3]: s=- [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 3 [ 16]: c=IN IP4 0.0.0.0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 16452 RTP/AVP 0 101 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Body 9 [ 10]: a=ptime:30 --- (12 headers 10 lines) --- [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 (Checking From) --From tag cd6102ad90f7604ci0 --To-tag as1b771f01 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.10.11 : 5060 (NAT) [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Found RTP audio format 0 Found RTP audio format 101 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:5282 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 0.0.0.0:16452 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/103-b790c580 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 0.0.0.0:16452 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 22 17:15:29] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:14109 handle_request_invite: Got a SIP re-invite for call 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:14204 handle_request_invite: SIP/103-b790c580: This call is UP.... [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:6952 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.5.1 port 19044 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 22 17:15:29] DEBUG[16983]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:6897 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-cc55a5e1;received=10.1.10.11 From: ;tag=cd6102ad90f7604ci0 To: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 101 INVITE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 232 v=0 o=root 16979 16980 IN IP4 10.1.5.1 s=session c=IN IP4 10.1.5.1 t=0 0 m=audio 19044 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 22 17:15:29] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #24 -- Started music on hold, class 'default', on SIP/101-081c6850 [Feb 22 17:15:29] DEBUG[16983]: channel.c:1910 ast_settimeout: Scheduling timer at 160 sample intervals [Feb 22 17:15:29] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:29] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 8 (On Hold) [Feb 22 17:15:29] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:29] DEBUG[16983]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Feb 22 17:15:29] DEBUG[16983]: channel.c:2760 set_format: Set channel SIP/101-081c6850 to write format slin [Feb 22 17:15:29] DEBUG[16983]: res_musiconhold.c:252 ast_moh_files_next: SIP/101-081c6850 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine' [Feb 22 17:15:29] DEBUG[16983]: rtp.c:2792 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 22 17:15:29] DEBUG[16983]: rtp.c:2809 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 <--- SIP read from 10.1.10.11:5060 ---> ACK sip:101@10.1.5.1 SIP/2.0 Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-7f2dfcd7 From: ;tag=cd6102ad90f7604ci0 To: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 101 ACK Max-Forwards: 70 Contact: "sip2" User-Agent: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 28]: ACK sip:101@10.1.5.1 SIP/2.0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 172.24.0.2:5060;branch=z9hG4bK-7f2dfcd7 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 54]: From: ;tag=cd6102ad90f7604ci0 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 47]: To: "unknown" ;tag=as1b771f01 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 13]: CSeq: 101 ACK [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 41]: Contact: "sip2" [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 36]: User-Agent: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 (Checking From) --From tag cd6102ad90f7604ci0 --To-tag as1b771f01 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #24 [Feb 22 17:15:29] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' of Response 101: Match Found RTCP SR transmission error, rtcp halted [Feb 22 17:15:30] NOTICE[16983]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 21! <--- SIP read from 192.168.170.244:5060 ---> BYE sip:103@192.168.168.35 SIP/2.0 Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc1a20000585b00000022 Content-Length: 0 Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 5 BYE From: "unknown";tag=3384804610551 Max-Forwards: 70 To: ;tag=as3569f33c User-Agent: SJphone/1.60.289a (SJ Labs) Authorization: Digest username="101",realm="asterisk",nonce="78f4082b",uri="sip:103@192.168.168.35:5060",response="cf81116355e3cd952b5601b5e54629f2",algorithm="MD5" <-------------> [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 34]: BYE sip:103@192.168.168.35 SIP/2.0 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002045ddc1a20000585b00000022 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 5 BYE [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 62]: From: "unknown";tag=3384804610551 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 48]: To: ;tag=as3569f33c [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [164]: Authorization: Digest username="101",realm="asterisk",nonce="78f4082b",uri="sip:103@192.168.168.35:5060",response="cf81116355e3cd952b5601b5e54629f2",algorithm="MD5" --- (10 headers 0 lines) --- [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 (Checking From) --From tag 3384804610551 --To-tag as3569f33c [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Their Tag 3384804610551 Our tag: as3569f33c [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15271 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:14797 handle_request_bye: Initializing initreq for method BYE - callid 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 Sending to 192.168.170.244 : 5060 (NAT) [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:1731 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:14854 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 192.168.170.244:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000002045ddc1a20000585b00000022;received=192.168.170.244;rport=5060 From: "unknown";tag=3384804610551 To: ;tag=as3569f33c Call-ID: 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11 CSeq: 5 BYE User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> -- Stopped music on hold on SIP/101-081c6850 [Feb 22 17:15:30] DEBUG[16983]: channel.c:2760 set_format: Set channel SIP/101-081c6850 to write format ulaw [Feb 22 17:15:30] DEBUG[16983]: channel.c:1910 ast_settimeout: Scheduling timer at 0 sample intervals [Feb 22 17:15:30] DEBUG[16983]: rtp.c:3213 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup [Feb 22 17:15:30] DEBUG[16983]: channel.c:3971 ast_channel_bridge: Returning from native bridge, channels: SIP/101-081c6850, SIP/103-b790c580 [Feb 22 17:15:30] DEBUG[16983]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/103-b790c580' [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3603 sip_hangup: Hangup call SIP/103-b790c580, SIP callid 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1) [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3612 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3349 update_call_counter: Call to peer '103' removed from call limit 2 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 Scheduling destruction of SIP dialog '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' in 6400 ms (Method: ACK) [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:6050 reqprep: Strict routing enforced for session 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 set_destination: Parsing for address/port to send to set_destination: set destination to 172.24.0.2, port 5060 Reliably Transmitting (NAT) to 10.1.10.11:5060: BYE sip:103@172.24.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK4bd09505;rport Max-Forwards: 70 From: "unknown" ;tag=as1b771f01 To: ;tag=cd6102ad90f7604ci0 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 103 BYE User-Agent: Asterisk PBX SVN-trunk-r56095 Content-Length: 0 --- [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #27 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-b790c580 [Feb 22 17:15:30] DEBUG[16983]: rtp.c:1566 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 22 17:15:30] DEBUG[16983]: app_dial.c:1710 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 22 17:15:30] DEBUG[16983]: pbx.c:2289 __ast_pbx_run: Spawn extension (from-sip,103,3) exited non-zero on 'SIP/101-081c6850' == Spawn extension (from-sip, 103, 3) exited non-zero on 'SIP/101-081c6850' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"unknown" <101>' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '101' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '103' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081c6850' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103-b790c580' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-22 17:15:13' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-22 17:15:17' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-22 17:15:30' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '17' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '13' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1172160913.0' [Feb 22 17:15:30] DEBUG[16983]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 22 17:15:30] DEBUG[16983]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/101-081c6850' [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3603 sip_hangup: Hangup call SIP/101-081c6850, SIP callid 1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11) [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3612 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:3349 update_call_counter: Call from peer '101' removed from call limit 2 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081c6850 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 8 (On Hold) [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 8 (On Hold) [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 103 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Feb 22 17:15:30] DEBUG[16983]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Feb 22 17:15:30] DEBUG[16983]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 22 17:15:30] DEBUG[16983]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Feb 22 17:15:30] DEBUG[16983]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Feb 22 17:15:30] DEBUG[16983]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '8' (On Hold) 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=cd6102ad90f7604ci0 From: "unknown" ;tag=as1b771f01 Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 CSeq: 103 BYE Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK4bd09505 Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 <-------------> [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 52]: To: ;tag=cd6102ad90f7604ci0 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 49]: From: "unknown" ;tag=as1b771f01 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 50]: Call-ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 13]: CSeq: 103 BYE [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK4bd09505 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 (Checking To) --From tag as1b771f01 --To-tag cd6102ad90f7604ci0 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 7ebae5e826bc6afe16ec84df02e18477@10.1.5.1 Their Tag cd6102ad90f7604ci0 Our tag: as1b771f01 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #27 [Feb 22 17:15:30] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' of Request 103: Match Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '7ebae5e826bc6afe16ec84df02e18477@10.1.5.1' Method: ACK Really destroying SIP dialog '1757D124-E379-4479-80A2-62090E4C3760@192.168.4.11' Method: BYE [Feb 22 17:15:34] DEBUG[16983]: chan_sip.c:2161 __sip_autodestruct: Auto destroying SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' [Feb 22 17:15:34] DEBUG[16983]: chan_sip.c:3401 sip_destroy: Destroying SIP dialog AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Really destroying SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' 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=z9hG4bKc0a8040b0000001045ddc1ae0000660c00000024 Content-Length: 0 Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 CSeq: 4 OPTIONS From: ;tag=3387757819986 Max-Forwards: 70 To: <-------------> [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0 [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000001045ddc1ae0000660c00000024 [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 58]: Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 15]: CSeq: 4 OPTIONS [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: From: ;tag=3387757819986 [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 29]: To: --- (8 headers 0 lines) --- [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 (Checking From) --From tag 3387757819986 --To-tag [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4727 find_call: = No match Their Call ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Their Tag 3385757813933 Our tag: as5c949e5d [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 - OPTIONS (No RTP) [Feb 22 17:15:42] DEBUG[16983]: chan_sip.c:15271 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=z9hG4bKc0a8040b0000001045ddc1ae0000660c00000024;received=192.168.170.244;rport=5060 From: ;tag=3387757819986 To: ;tag=as7ebfac82 Call-ID: AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 CSeq: 4 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r56095 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' in 32000 ms (Method: OPTIONS) [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method OPTIONS - callid 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 39]: OPTIONS sip:103@172.24.0.2:5060 SIP/2.0 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 59]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK3c19db9e;rport [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 55]: From: "asterisk" ;tag=as290e046d [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 29]: To: [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 50]: Call-ID: 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56095 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 35]: Date: Thu, 22 Feb 2007 16:15:44 GMT [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 19]: Supported: replaces [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 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=z9hG4bK3c19db9e;rport Max-Forwards: 70 From: "asterisk" ;tag=as290e046d To: Contact: Call-ID: 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r56095 Date: Thu, 22 Feb 2007 16:15:44 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #29 <--- SIP read from 10.1.10.11:5060 ---> SIP/2.0 200 OK To: ;tag=bebb151753e7caa0i0 From: "asterisk" ;tag=as290e046d Call-ID: 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 CSeq: 102 OPTIONS Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK3c19db9e Server: Linksys/SPA901-4.1.11(c) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER <-------------> [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 52]: To: ;tag=bebb151753e7caa0i0 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 55]: From: "asterisk" ;tag=as290e046d [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 50]: Call-ID: 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 17]: CSeq: 102 OPTIONS [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK3c19db9e [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 32]: Server: Linksys/SPA901-4.1.11(c) [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 17]: Content-Length: 0 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER --- (9 headers 0 lines) --- [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 (Checking To) --From tag as290e046d --To-tag bebb151753e7caa0i0 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1 Their Tag Our tag: as290e046d [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #29 [Feb 22 17:15:44] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1' of Request 102: Match Found Really destroying SIP dialog '11fe348d7f5d3ead4b6f8c877ee1d464@10.1.5.1' Method: OPTIONS [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method OPTIONS - callid 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 44]: OPTIONS sip:101@192.168.170.244:5060 SIP/2.0 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.168.35:5060;branch=z9hG4bK63fe0a08;rport [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as0bd2dc62 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 34]: To: [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 38]: Contact: [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 56]: Call-ID: 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56095 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 9 [ 35]: Date: Thu, 22 Feb 2007 16:15:45 GMT [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 11 [ 19]: Supported: replaces [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 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=z9hG4bK63fe0a08;rport Max-Forwards: 70 From: "asterisk" ;tag=as0bd2dc62 To: Contact: Call-ID: 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r56095 Date: Thu, 22 Feb 2007 16:15:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32 <--- 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=z9hG4bK63fe0a08 Content-Length: 0 Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY Call-ID: 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 CSeq: 102 OPTIONS From: "asterisk";tag=as0bd2dc62 Server: SJphone/1.60.289a (SJ Labs) To: "unknown" <-------------> [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 0 [ 30]: SIP/2.0 405 Method Not Allowed [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 192.168.168.35:5060;rport=5060;received=192.168.168.35;branch=z9hG4bK63fe0a08 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 2 [ 17]: Content-Length: 0 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 3 [ 46]: Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 4 [ 56]: Call-ID: 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 6 [ 60]: From: "asterisk";tag=as0bd2dc62 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 7 [ 35]: Server: SJphone/1.60.289a (SJ Labs) [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4941 parse_request: Header 8 [ 43]: To: "unknown" --- (9 headers 0 lines) --- [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4700 find_call: = Looking for Call ID: 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 (Checking To) --From tag as0bd2dc62 --To-tag [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:4727 find_call: = Found Their Call ID: 3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35 Their Tag Our tag: as0bd2dc62 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32 [Feb 22 17:15:45] DEBUG[16983]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35' of Request 102: Match Found Really destroying SIP dialog '3059f22a2fa2ec3f714a53d06e7d40ba@192.168.168.35' Method: OPTIONS sip show inuse * User name In use Limit * Peer name In use Limit 103 0/0/1 2 102 0/0/0 2 101 0/0/1 2 *CLI> sipcore h[Feb 22 17:15:54] DEBUG[16983]: chan_sip.c:2161 __sip_autodestruct: Auto destroying SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' [Feb 22 17:15:54] DEBUG[16983]: chan_sip.c:3401 sip_destroy: Destroying SIP dialog AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11 Really destroying SIP dialog 'AD7625D7-A589-4E96-AEBC-9E6C7DCAD407@192.168.4.11' Method: OPTIONS show hints -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:Hold Watchers 0 102@from-sip : SIP/102 State:Unavailable Watchers 0 101@from-sip : SIP/101 State:Hold Watchers 0 ---------------- - 3 hints registered *CLI> stop now