<--- 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=z9hG4bKc0a8040b0000002245d2baf900002dba00000022
Content-Length: 343
Contact: <sip:101@192.168.170.244:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Content-Type: application/sdp
CSeq: 1 INVITE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>
User-Agent: SJphone/1.60.289a (SJ Labs)

v=0
o=- 3380427129 3380427129 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 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2baf900002dba00000022
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 19]: Content-Length: 343
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 39]: Contact: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 14]: CSeq: 1 INVITE
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 16]: Max-Forwards: 70
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 33]: To: <sip:103@192.168.168.35:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [  0]: 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 48]: o=- 3380427129 3380427129 IN IP4 192.168.170.244
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=SJphone
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 24]: c=IN IP4 192.168.170.244
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 18]: a=direction:active
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 37]: m=audio 49154 RTP/AVP 3 97 98 8 0 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 19]: a=rtpmap:3 GSM/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 21]: a=rtpmap:97 iLBC/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  9 [ 21]: a=rtpmap:98 iLBC/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 10 [ 17]: a=fmtp:98 mode=20
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 11 [ 20]: a=rtpmap:8 PCMA/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 12 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 13 [ 33]: a=rtpmap:101 telephone-event/8000
--- (11 headers 14 lines) ---
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag   
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11 Their Tag 82510925252 Our tag: as06bca392
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: a68d467a-1af0fdf@172.24.0.2 Their Tag e69107af299cb8e6o0 Our tag: as6b263dfe
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 77C3CB9D-27D7-4122-AA43-4A8DAB9C24AC@192.168.4.11 Their Tag 805750413 Our tag: as1079771b
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11 Their Tag 80510923391 Our tag: as66fc1768
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2795 do_setnat: Setting NAT on RTP to Off
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2800 do_setnat: Setting NAT on VRTP to Off
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2805 do_setnat: Setting NAT on UDPTL to Off
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4517 sip_alloc: Allocating new SIP dialog for 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 - INVITE (With RTP)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:13603 handle_request_invite: Initializing initreq for method INVITE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Using INVITE request as basis request - 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
No user '101' in SIP users list
Found peer '101' for '101' from 192.168.170.244:5060
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2795 do_setnat: Setting NAT on RTP to On
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2800 do_setnat: Setting NAT on VRTP to On
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2805 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=z9hG4bKc0a8040b0000002245d2baf900002dba00000022;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as69318a6b
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 1 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1906fe3f"
Content-Length: 0


<------------>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #74
Scheduling destruction of SIP dialog '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' in 1664 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=z9hG4bKc0a8040b0000002245d2baf900002dba00000022
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 1 ACK
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as69318a6b
User-Agent: SJphone/1.60.289a (SJ Labs)

<------------->
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 39]: ACK sip:103@192.168.168.35:5060 SIP/2.0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2baf900002dba00000022
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 1 ACK
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as69318a6b
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
--- (9 headers 0 lines) ---
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as69318a6b  
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as69318a6b
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #74
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '8AB6C795-7671-43EB-9F91-9286FE96C3C4@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=z9hG4bKc0a8040b0000002245d2baf90000010d00000023
Content-Length: 343
Contact: <sip:101@192.168.170.244:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Content-Type: application/sdp
CSeq: 2 INVITE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>
User-Agent: SJphone/1.60.289a (SJ Labs)
Authorization: Digest username="101",realm="asterisk",nonce="1906fe3f",uri="sip:103@192.168.168.35:5060",response="6849d72da2292494c38b9416f43d0cd0",algorithm="MD5"

v=0
o=- 3380427129 3380427129 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 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 42]: INVITE sip:103@192.168.168.35:5060 SIP/2.0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2baf90000010d00000023
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 19]: Content-Length: 343
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 39]: Contact: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 14]: CSeq: 2 INVITE
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 16]: Max-Forwards: 70
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 33]: To: <sip:103@192.168.168.35:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [164]: Authorization: Digest username="101",realm="asterisk",nonce="1906fe3f",uri="sip:103@192.168.168.35:5060",response="6849d72da2292494c38b9416f43d0cd0",algorithm="MD5"
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 12 [  0]: 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 48]: o=- 3380427129 3380427129 IN IP4 192.168.170.244
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=SJphone
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 24]: c=IN IP4 192.168.170.244
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 18]: a=direction:active
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 37]: m=audio 49154 RTP/AVP 3 97 98 8 0 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 19]: a=rtpmap:3 GSM/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 21]: a=rtpmap:97 iLBC/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  9 [ 21]: a=rtpmap:98 iLBC/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 10 [ 17]: a=fmtp:98 mode=20
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 11 [ 20]: a=rtpmap:8 PCMA/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 12 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 13 [ 33]: a=rtpmap:101 telephone-event/8000
--- (12 headers 14 lines) ---
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag   
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as69318a6b
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:13603 handle_request_invite: Initializing initreq for method INVITE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Using INVITE request as basis request - 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
No user '101' in SIP users list
Found peer '101' for '101' from 192.168.170.244:5060
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2795 do_setnat: Setting NAT on RTP to On
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2800 do_setnat: Setting NAT on VRTP to On
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2805 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 14 08:31:39] DEBUG[20527]: chan_sip.c:5083 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 14 08:31:39] DEBUG[20527]: chan_sip.c:5313 process_sdp: T38 state changed to 0 on channel <none>
Capabilities: us - 0x4 (ulaw), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=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 14 08:31:39] DEBUG[20527]: chan_sip.c:5393 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:13684 handle_request_invite: Checking SIP call limits for device 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:3240 update_call_counter: Updating call counter for incoming call
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:3310 update_call_counter: Call from peer '101' is 1 out of 2
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:382 __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 14 08:31:39] DEBUG[20527]: chan_sip.c:4020 sip_new: *** Our native formats are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4021 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4022 sip_new: *** Our capabilities are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4023 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4046 sip_new: This channel will not be able to handle video.
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:8141 build_route: build_route: Contact hop: <sip:101@192.168.170.244:5060>
list_route: hop: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:13759 handle_request_invite: SIP/101-081bd6e8: 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=z9hG4bKc0a8040b0000002245d2baf90000010d00000023;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 2 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Length: 0


<------------>
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081bd6e8
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 2 (In use)
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 2 (In use)
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:39] DEBUG[20527]: pbx.c:1693 pbx_extension_helper: Launching 'Dial'
    -- Executing [103@from-sip:1] Dial("SIP/101-081bd6e8", "SIP/103") in new stack
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15587 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4517 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2841 create_addr_from_peer: Our T38 capability (3856)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2795 do_setnat: Setting NAT on RTP to On
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2805 do_setnat: Setting NAT on UDPTL to On
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:1770 obproxy_get: OBPROXY: Not applying OBproxy to this call
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4020 sip_new: *** Our native formats are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4021 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4022 sip_new: *** Our capabilities are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4023 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4025 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4046 sip_new: This channel will not be able to handle video.
[Feb 14 08:31:39] DEBUG[20527]: channel.c:3203 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-1.
[Feb 14 08:31:39] DEBUG[20527]: channel.c:3203 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Feb 14 08:31:39] DEBUG[20527]: channel.c:3203 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Feb 14 08:31:39] DEBUG[20527]: channel.c:3203 ast_channel_inherit_variables: Not copying variable SIPURI.
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:3059 sip_call: Outgoing Call for 103
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:3240 update_call_counter: Updating call counter for outgoing call
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:3310 update_call_counter: Call to peer '103' is 1 out of 2
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/103 - state 6 (Ringing)
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:3077 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:6397 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:6398 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
Audio is at 10.1.5.1 port 15074
Adding codec 0x4 (ulaw) to SDP
[Feb 14 08:31:39] DEBUG[20527]: 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.
Adding non-codec 0x1 (telephone-event) to SDP
[Feb 14 08:31:39] DEBUG[20527]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Feb 14 08:31:39] DEBUG[20527]: 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 14 08:31:39] DEBUG[20527]: chan_sip.c:6523 add_sdp: -- Done with adding codecs to SDP
[Feb 14 08:31:39] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:6567 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:1705 initialize_initreq: Initializing initreq for method INVITE - callid 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 38]: INVITE sip:103@172.24.0.2:5060 SIP/2.0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 59]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5;rport
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 16]: Max-Forwards: 70
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 49]: From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 29]: To: <sip:103@172.24.0.2:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 27]: Contact: <sip:101@10.1.5.1>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 50]: Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 16]: CSeq: 102 INVITE
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r54149
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 35]: Date: Wed, 14 Feb 2007 07:31:39 GMT
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [ 19]: Supported: replaces
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 12 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 13 [ 19]: Content-Length: 232
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 14 [  0]: 
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 34]: o=root 20523 20523 IN IP4 10.1.5.1
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=session
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 17]: c=IN IP4 10.1.5.1
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 27]: m=audio 15074 RTP/AVP 0 101
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 33]: a=rtpmap:101 telephone-event/8000
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 15]: a=fmtp:101 0-16
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  9 [ 25]: a=silenceSupp:off - - - -
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body 10 [ 10]: a=ptime:20
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 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=z9hG4bK2e4e52f5;rport
Max-Forwards: 70
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
To: <sip:103@172.24.0.2:5060>
Contact: <sip:101@10.1.5.1>
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 102 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Date: Wed, 14 Feb 2007 07:31:39 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 232

v=0
o=root 20523 20523 IN IP4 10.1.5.1
s=session
c=IN IP4 10.1.5.1
t=0 0
m=audio 15074 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 14 08:31:39] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #76
    -- Called 103

<--- SIP read from 10.1.10.11:5060 --->
SIP/2.0 100 Trying
To: <sip:103@172.24.0.2:5060>
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5
Server: Linksys/SPA901-4.1.11(c)
Content-Length: 0

<------------->
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 18]: SIP/2.0 100 Trying
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 29]: To: <sip:103@172.24.0.2:5060>
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 49]: From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 50]: Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 16]: CSeq: 102 INVITE
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 32]: Server: Linksys/SPA901-4.1.11(c)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 17]: Content-Length: 0
--- (8 headers 0 lines) ---
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 (Checking To) --From tag as51ad4559 --To-tag   
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag  Our tag: as51ad4559
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2255 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #76 - INVITE (got response)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2264 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1' Request 102: Found
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:11921 handle_response_invite: SIP response 100 to standard invite

<--- SIP read from 10.1.10.11:5060 --->
SIP/2.0 180 Ringing
To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5
Server: Linksys/SPA901-4.1.11(c)
Content-Length: 0

<------------->
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 19]: SIP/2.0 180 Ringing
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 52]: To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 49]: From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 50]: Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 16]: CSeq: 102 INVITE
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 32]: Server: Linksys/SPA901-4.1.11(c)
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 17]: Content-Length: 0
--- (8 headers 0 lines) ---
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 (Checking To) --From tag as51ad4559 --To-tag a6f0ca54b388d36bi0  
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag  Our tag: as51ad4559
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:2264 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1' Request 102: Found
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:11921 handle_response_invite: SIP response 180 to standard invite
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081bbf88
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
    -- SIP/103-081bbf88 is ringing
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/103 - state 6 (Ringing)
[Feb 14 08:31:39] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:39] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:39] DEBUG[20527]: 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.

<--- Transmitting (NAT) to 192.168.170.244:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.170.244;branch=z9hG4bKc0a8040b0000002245d2baf90000010d00000023;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 2 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Length: 0


<------------>

<--- SIP read from 10.1.10.11:5060 --->
SIP/2.0 200 OK
To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5
Contact: "sip2" <sip:103@172.24.0.2:5060>
Server: Linksys/SPA901-4.1.11(c)
Content-Length: 198
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Content-Type: application/sdp

v=0
o=- 1840 1840 IN IP4 172.24.0.2
s=-
c=IN IP4 172.24.0.2
t=0 0
m=audio 16414 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 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 14]: SIP/2.0 200 OK
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 52]: To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 49]: From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 50]: Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 16]: CSeq: 102 INVITE
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK2e4e52f5
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 41]: Contact: "sip2" <sip:103@172.24.0.2:5060>
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 32]: Server: Linksys/SPA901-4.1.11(c)
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 19]: Content-Length: 198
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [  0]: 
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 31]: o=- 1840 1840 IN IP4 172.24.0.2
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  3]: s=-
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 19]: c=IN IP4 172.24.0.2
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 27]: m=audio 16414 RTP/AVP 0 101
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 33]: a=rtpmap:101 telephone-event/8000
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 15]: a=fmtp:101 0-15
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  9 [ 10]: a=ptime:30
--- (11 headers 10 lines) ---
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 (Checking To) --From tag as51ad4559 --To-tag a6f0ca54b388d36bi0  
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:2205 __sip_ack: Acked pending invite 102
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1' of Request 102: Match Found
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:11921 handle_response_invite: SIP response 200 to standard invite
Found RTP audio format 0
Found RTP audio format 101
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:5083 process_sdp: Peer doesn't provide T.38 UDPTL
Peer audio RTP is at port 172.24.0.2:16414
Found description format PCMU for ID 0
Found description format telephone-event for ID 101
Got unsupported a:fmtp in SDP offer 
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:5313 process_sdp: T38 state changed to 0 on channel SIP/103-081bbf88
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=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:16414
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:5393 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:5400 process_sdp: We have an owner, now see if we need to change this call
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:5416 process_sdp: Setting call off HOLD! - 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:3240 update_call_counter: Updating call counter for outgoing call
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:8141 build_route: build_route: Contact hop: "sip2" <sip:103@172.24.0.2:5060>
list_route: hop: <sip:103@172.24.0.2:5060>
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:5832 reqprep: Strict routing enforced for session 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
set_destination: Parsing <sip:103@172.24.0.2:5060> 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=z9hG4bK7cffe305;rport
Max-Forwards: 70
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
Contact: <sip:101@10.1.5.1>
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 102 ACK
User-Agent: Asterisk PBX SVN-trunk-r54149
Content-Length: 0


---
    -- Call on SIP/103-081bbf88 left from hold
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081bbf88
    -- SIP/103-081bbf88 answered SIP/101-081bd6e8
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/103 - state 2 (In use)
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/103 - state 2 (In use)
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081bd6e8
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:3682 sip_answer: SIP answering channel: SIP/101-081bd6e8
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 2 (In use)
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:6622 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:6397 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Feb 14 08:31:43] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:6398 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Feb 14 08:31:43] DEBUG[20527]: 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 14 08:31:43] DEBUG[20527]: 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 14 08:31:43] DEBUG[20527]: 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.
Audio is at 192.168.168.35 port 14940
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:6523 add_sdp: -- Done with adding codecs to SDP
[Feb 14 08:31:43] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:6567 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=z9hG4bKc0a8040b0000002245d2baf90000010d00000023;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 2 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Type: application/sdp
Content-Length: 244

v=0
o=root 20523 20523 IN IP4 192.168.168.35
s=session
c=IN IP4 192.168.168.35
t=0 0
m=audio 14940 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 14 08:31:43] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #78

<--- 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=z9hG4bKc0a8040b0000002245d2bafc00002b5500000027
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 2 ACK
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

<------------->
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bafc00002b5500000027
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 2 ACK
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
--- (9 headers 0 lines) ---
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #78
[Feb 14 08:31:43] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' of Response 2: Match Found
    -- Packet2Packet bridging SIP/101-081bd6e8 and SIP/103-081bbf88
[Feb 14 08:31:43] DEBUG[20527]: rtp.c:1218 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 10.1.10.11:16414

<--- 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=z9hG4bKc0a8040b0000002245d2baff0000716a00000028
Content-Length: 217
Contact: <sip:101@192.168.170.244:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Content-Type: application/sdp
CSeq: 3 INVITE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

v=0
o=- 3380427129 3380427130 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 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 37]: INVITE sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2baff0000716a00000028
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 19]: Content-Length: 217
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 39]: Contact: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 14]: CSeq: 3 INVITE
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 16]: Max-Forwards: 70
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [  0]: 
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 48]: o=- 3380427129 3380427130 IN IP4 192.168.170.244
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=SJphone
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 16]: c=IN IP4 0.0.0.0
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 18]: a=direction:active
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 27]: m=audio 49154 RTP/AVP 0 101
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 33]: a=rtpmap:101 telephone-event/8000
--- (11 headers 9 lines) ---
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:13603 handle_request_invite: Initializing initreq for method INVITE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Found RTP audio format 0
Found RTP audio format 101
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:5083 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 14 08:31:45] DEBUG[20527]: chan_sip.c:5313 process_sdp: T38 state changed to 0 on channel SIP/101-081bd6e8
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=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 14 08:31:45] DEBUG[20527]: chan_sip.c:5393 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:5400 process_sdp: We have an owner, now see if we need to change this call
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:5422 process_sdp: Setting call on HOLD! - 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:45] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:13737 handle_request_invite: Got a SIP re-invite for call 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:13832 handle_request_invite: SIP/101-081bd6e8: This call is UP.... 
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:6622 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:6397 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:6398 add_sdp: ** Our prefcodec: 0x0 (nothing) 
Audio is at 192.168.168.35 port 14940
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:6523 add_sdp: -- Done with adding codecs to SDP
[Feb 14 08:31:45] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:6567 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=z9hG4bKc0a8040b0000002245d2baff0000716a00000028;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 3 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Type: application/sdp
Content-Length: 244

v=0
o=root 20523 20524 IN IP4 192.168.168.35
s=session
c=IN IP4 192.168.168.35
t=0 0
m=audio 14940 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 14 08:31:45] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #79
    -- Started music on hold, class 'default', on SIP/103-081bbf88
[Feb 14 08:31:45] DEBUG[20527]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals
[Feb 14 08:31:45] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:45] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 8 (On Hold)
[Feb 14 08:31:45] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:45] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:45] DEBUG[20527]: channel.c:2243 __ast_read: Generator got voice, switching to phase locked mode
[Feb 14 08:31:45] DEBUG[20527]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals
[Feb 14 08:31:45] DEBUG[20527]: channel.c:2753 set_format: Set channel SIP/103-081bbf88 to write format slin
[Feb 14 08:31:45] DEBUG[20527]: res_musiconhold.c:252 ast_moh_files_next: SIP/103-081bbf88 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine'
[Feb 14 08:31:45] DEBUG[20527]: rtp.c:2757 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Feb 14 08:31:45] DEBUG[20527]: rtp.c:2774 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Feb 14 08:31:45] DEBUG[20527]: 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 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=z9hG4bKc0a8040b0000002245d2baff00007b4f0000002a
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 3 ACK
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

<------------->
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2baff00007b4f0000002a
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 3 ACK
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
--- (9 headers 0 lines) ---
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #79
[Feb 14 08:31:45] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' of Response 3: Match Found
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:46] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 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=z9hG4bKc0a8040b0000002245d2bb010000085f0000002b
Content-Length: 225
Contact: <sip:101@192.168.170.244:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Content-Type: application/sdp
CSeq: 4 INVITE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

v=0
o=- 3380427129 3380427131 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 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 37]: INVITE sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb010000085f0000002b
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 19]: Content-Length: 225
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 39]: Contact: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 14]: CSeq: 4 INVITE
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 16]: Max-Forwards: 70
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [  0]: 
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 48]: o=- 3380427129 3380427131 IN IP4 192.168.170.244
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=SJphone
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 24]: c=IN IP4 192.168.170.244
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 18]: a=direction:active
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 27]: m=audio 49154 RTP/AVP 0 101
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 33]: a=rtpmap:101 telephone-event/8000
--- (11 headers 9 lines) ---
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:13603 handle_request_invite: Initializing initreq for method INVITE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Found RTP audio format 0
Found RTP audio format 101
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:5083 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 14 08:31:47] DEBUG[20527]: chan_sip.c:5313 process_sdp: T38 state changed to 0 on channel SIP/101-081bd6e8
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=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 14 08:31:47] DEBUG[20527]: chan_sip.c:5393 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:5400 process_sdp: We have an owner, now see if we need to change this call
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:5416 process_sdp: Setting call off HOLD! - 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:13737 handle_request_invite: Got a SIP re-invite for call 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:13832 handle_request_invite: SIP/101-081bd6e8: This call is UP.... 
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:6622 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:6397 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:6398 add_sdp: ** Our prefcodec: 0x0 (nothing) 
Audio is at 192.168.168.35 port 14940
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:6523 add_sdp: -- Done with adding codecs to SDP
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:6567 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=z9hG4bKc0a8040b0000002245d2bb010000085f0000002b;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 4 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Type: application/sdp
Content-Length: 244

v=0
o=root 20523 20525 IN IP4 192.168.168.35
s=session
c=IN IP4 192.168.168.35
t=0 0
m=audio 14940 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 14 08:31:47] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #81
    -- Stopped music on hold on SIP/103-081bbf88
[Feb 14 08:31:47] DEBUG[20527]: channel.c:2753 set_format: Set channel SIP/103-081bbf88 to write format ulaw
[Feb 14 08:31:47] DEBUG[20527]: channel.c:1908 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=z9hG4bKc0a8040b0000002245d2bb01000063650000002d
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 4 ACK
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

<------------->
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb01000063650000002d
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 4 ACK
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
--- (9 headers 0 lines) ---
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #81
[Feb 14 08:31:47] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' of Response 4: Match Found
[Feb 14 08:31:49] DEBUG[20527]: chan_sip.c:2148 __sip_autodestruct: Auto destroying SIP dialog 'E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11'
[Feb 14 08:31:49] DEBUG[20527]: chan_sip.c:3336 sip_destroy: Destroying SIP dialog E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11
Really destroying SIP dialog 'E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11' Method: OPTIONS
[Feb 14 08:31:50] DEBUG[20527]: chan_sip.c:2148 __sip_autodestruct: Auto destroying SIP dialog '77C3CB9D-27D7-4122-AA43-4A8DAB9C24AC@192.168.4.11'
[Feb 14 08:31:50] DEBUG[20527]: chan_sip.c:3336 sip_destroy: Destroying SIP dialog 77C3CB9D-27D7-4122-AA43-4A8DAB9C24AC@192.168.4.11
Really destroying SIP dialog '77C3CB9D-27D7-4122-AA43-4A8DAB9C24AC@192.168.4.11' Method: REGISTER

<--- 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=z9hG4bKc0a8040b0000002245d2bb04000004620000002e
Content-Length: 217
Contact: <sip:101@192.168.170.244:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Content-Type: application/sdp
CSeq: 5 INVITE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

v=0
o=- 3380427129 3380427132 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 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 37]: INVITE sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb04000004620000002e
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 19]: Content-Length: 217
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 39]: Contact: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 14]: CSeq: 5 INVITE
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 16]: Max-Forwards: 70
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [  0]: 
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 48]: o=- 3380427129 3380427132 IN IP4 192.168.170.244
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=SJphone
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 16]: c=IN IP4 0.0.0.0
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 18]: a=direction:active
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 27]: m=audio 49154 RTP/AVP 0 101
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 33]: a=rtpmap:101 telephone-event/8000
--- (11 headers 9 lines) ---
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:13603 handle_request_invite: Initializing initreq for method INVITE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Found RTP audio format 0
Found RTP audio format 101
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:5083 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 14 08:31:51] DEBUG[20527]: chan_sip.c:5313 process_sdp: T38 state changed to 0 on channel SIP/101-081bd6e8
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=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 14 08:31:51] DEBUG[20527]: chan_sip.c:5393 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:5400 process_sdp: We have an owner, now see if we need to change this call
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:5422 process_sdp: Setting call on HOLD! - 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:51] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:13737 handle_request_invite: Got a SIP re-invite for call 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:13832 handle_request_invite: SIP/101-081bd6e8: This call is UP.... 
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:6622 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:6397 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:6398 add_sdp: ** Our prefcodec: 0x0 (nothing) 
Audio is at 192.168.168.35 port 14940
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:6523 add_sdp: -- Done with adding codecs to SDP
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:6567 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=z9hG4bKc0a8040b0000002245d2bb04000004620000002e;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 5 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Type: application/sdp
Content-Length: 244

v=0
o=root 20523 20526 IN IP4 192.168.168.35
s=session
c=IN IP4 192.168.168.35
t=0 0
m=audio 14940 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 14 08:31:51] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #82
    -- Started music on hold, class 'default', on SIP/103-081bbf88
[Feb 14 08:31:51] DEBUG[20527]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals
[Feb 14 08:31:51] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:51] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 8 (On Hold)
[Feb 14 08:31:51] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:51] DEBUG[20527]: 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 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2243 __ast_read: Generator got voice, switching to phase locked mode
[Feb 14 08:31:51] DEBUG[20527]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2753 set_format: Set channel SIP/103-081bbf88 to write format slin
[Feb 14 08:31:51] DEBUG[20527]: res_musiconhold.c:252 ast_moh_files_next: SIP/103-081bbf88 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine'
[Feb 14 08:31:51] DEBUG[20527]: rtp.c:2626 ast_rtp_raw_write: Difference is 25592, ms is 3219

<--- 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=z9hG4bKc0a8040b0000002245d2bb040000213500000030
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 5 ACK
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

<------------->
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb040000213500000030
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 5 ACK
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
--- (9 headers 0 lines) ---
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #82
[Feb 14 08:31:51] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' of Response 5: Match Found
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:51] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:52] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27)
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 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=z9hG4bKc0a8040b0000002245d2bb060000498e00000031
Content-Length: 225
Contact: <sip:101@192.168.170.244:5060>
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Content-Type: application/sdp
CSeq: 6 INVITE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

v=0
o=- 3380427129 3380427133 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 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 37]: INVITE sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb060000498e00000031
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 19]: Content-Length: 225
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 39]: Contact: <sip:101@192.168.170.244:5060>
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 29]: Content-Type: application/sdp
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 14]: CSeq: 6 INVITE
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 16]: Max-Forwards: 70
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header 11 [  0]: 
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  0 [  3]: v=0
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  1 [ 48]: o=- 3380427129 3380427133 IN IP4 192.168.170.244
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  2 [  9]: s=SJphone
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  3 [ 24]: c=IN IP4 192.168.170.244
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  4 [  5]: t=0 0
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  5 [ 18]: a=direction:active
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  6 [ 27]: m=audio 49154 RTP/AVP 0 101
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  7 [ 20]: a=rtpmap:0 PCMU/8000
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:    Body  8 [ 33]: a=rtpmap:101 telephone-event/8000
--- (11 headers 9 lines) ---
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:13603 handle_request_invite: Initializing initreq for method INVITE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Found RTP audio format 0
Found RTP audio format 101
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:5083 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 14 08:31:53] DEBUG[20527]: chan_sip.c:5313 process_sdp: T38 state changed to 0 on channel SIP/101-081bd6e8
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=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 14 08:31:53] DEBUG[20527]: chan_sip.c:5393 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:5400 process_sdp: We have an owner, now see if we need to change this call
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:5416 process_sdp: Setting call off HOLD! - 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:13737 handle_request_invite: Got a SIP re-invite for call 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:13832 handle_request_invite: SIP/101-081bd6e8: This call is UP.... 
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:6622 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:6397 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:6398 add_sdp: ** Our prefcodec: 0x0 (nothing) 
Audio is at 192.168.168.35 port 14940
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:6523 add_sdp: -- Done with adding codecs to SDP
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2292 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:6567 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=z9hG4bKc0a8040b0000002245d2bb060000498e00000031;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 6 INVITE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Type: application/sdp
Content-Length: 244

v=0
o=root 20523 20527 IN IP4 192.168.168.35
s=session
c=IN IP4 192.168.168.35
t=0 0
m=audio 14940 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 14 08:31:53] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #83
    -- Stopped music on hold on SIP/103-081bbf88
[Feb 14 08:31:53] DEBUG[20527]: channel.c:2753 set_format: Set channel SIP/103-081bbf88 to write format ulaw
[Feb 14 08:31:53] DEBUG[20527]: channel.c:1908 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=z9hG4bKc0a8040b0000002245d2bb060000197900000033
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 6 ACK
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)

<------------->
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 34]: ACK sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb060000197900000033
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 6 ACK
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
--- (9 headers 0 lines) ---
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #83
[Feb 14 08:31:53] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' of Response 6: Match Found

<--- 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=z9hG4bKc0a8040b0000002245d2bb0b00003e7f00000034
Content-Length: 0
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 7 BYE
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
Max-Forwards: 70
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
User-Agent: SJphone/1.60.289a (SJ Labs)
Authorization: Digest username="101",realm="asterisk",nonce="1906fe3f",uri="sip:103@192.168.168.35:5060",response="6849d72da2292494c38b9416f43d0cd0",algorithm="MD5"

<------------->
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 34]: BYE sip:103@192.168.168.35 SIP/2.0
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000002245d2bb0b00003e7f00000034
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 11]: CSeq: 7 BYE
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 60]: From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 48]: To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  9 [164]: Authorization: Digest username="101",realm="asterisk",nonce="1906fe3f",uri="sip:103@192.168.168.35:5060",response="6849d72da2292494c38b9416f43d0cd0",algorithm="MD5"
--- (10 headers 0 lines) ---
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 (Checking From) --From tag 82668714857 --To-tag as653d36ef  
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11 Their Tag 82668714857 Our tag: as653d36ef
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:14892 handle_request: **** Received BYE (8) - Command in SIP BYE
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:14425 handle_request_bye: Initializing initreq for method BYE - callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
Sending to 192.168.170.244 : 5060 (NAT)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:1718 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:14475 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=z9hG4bKc0a8040b0000002245d2bb0b00003e7f00000034;received=192.168.170.244;rport=5060
From: "unknown"<sip:101@192.168.168.35:5060>;tag=82668714857
To: <sip:103@192.168.168.35:5060>;tag=as653d36ef
Call-ID: 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11
CSeq: 7 BYE
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:103@192.168.168.35>
Content-Length: 0


<------------>
[Feb 14 08:31:57] DEBUG[20527]: rtp.c:3162 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup
[Feb 14 08:31:57] DEBUG[20527]: channel.c:3963 ast_channel_bridge: Returning from native bridge, channels: SIP/101-081bd6e8, SIP/103-081bbf88
[Feb 14 08:31:57] DEBUG[20527]: channel.c:1589 ast_hangup: Hanging up channel 'SIP/103-081bbf88'
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3533 sip_hangup: Hangup call SIP/103-081bbf88, SIP callid 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3541 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3240 update_call_counter: Updating call counter for outgoing call
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3284 update_call_counter: Call to peer '103' removed from call limit 2
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103
Scheduling destruction of SIP dialog '4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1' in 6400 ms (Method: INVITE)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:5832 reqprep: Strict routing enforced for session 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
set_destination: Parsing <sip:103@172.24.0.2:5060> 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=z9hG4bK6a16c506;rport
Max-Forwards: 70
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 103 BYE
User-Agent: Asterisk PBX SVN-trunk-r54149
Content-Length: 0


---
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:2102 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #85
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081bbf88
[Feb 14 08:31:57] DEBUG[20527]: rtp.c:1556 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Feb 14 08:31:57] DEBUG[20527]: app_dial.c:1698 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:2289 __ast_pbx_run: Spawn extension (from-sip,103,1) exited non-zero on 'SIP/101-081bd6e8'
  == Spawn extension (from-sip, 103, 1) exited non-zero on 'SIP/101-081bd6e8'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"unknown" <101>'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '101'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '103'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'from-sip'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081bd6e8'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103-081bbf88'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/103'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-14 08:31:39'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-14 08:31:43'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-14 08:31:57'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '18'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '14'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1171438299.1'
[Feb 14 08:31:57] DEBUG[20527]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is ''
[Feb 14 08:31:57] DEBUG[20527]: channel.c:1589 ast_hangup: Hanging up channel 'SIP/101-081bd6e8'
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3533 sip_hangup: Hangup call SIP/101-081bd6e8, SIP callid 8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3541 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3240 update_call_counter: Updating call counter for incoming call
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:3284 update_call_counter: Call from peer '101' removed from call limit 2
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081bd6e8
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/103 - state 1 (Not in use)
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/103 - state 1 (Not in use)
[Feb 14 08:31:57] DEBUG[20527]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 103
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 103
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:57] DEBUG[20527]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 8 (On Hold)
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:366 do_state_change: Changing state for SIP/101 - state 8 (On Hold)
[Feb 14 08:31:57] DEBUG[20527]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 101
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:15518 sip_devicestate: Checking device state for peer 101
[Feb 14 08:31:57] DEBUG[20527]: 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 14 08:31:57] DEBUG[20527]: 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: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
CSeq: 103 BYE
Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK6a16c506
Server: Linksys/SPA901-4.1.11(c)
Content-Length: 0

<------------->
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 14]: SIP/2.0 200 OK
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 52]: To: <sip:103@172.24.0.2:5060>;tag=a6f0ca54b388d36bi0
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 49]: From: "unknown" <sip:101@10.1.5.1>;tag=as51ad4559
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 50]: Call-ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 13]: CSeq: 103 BYE
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 53]: Via: SIP/2.0/UDP 10.1.5.1:5060;branch=z9hG4bK6a16c506
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 32]: Server: Linksys/SPA901-4.1.11(c)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 17]: Content-Length: 0
--- (8 headers 0 lines) ---
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 (Checking To) --From tag as51ad4559 --To-tag a6f0ca54b388d36bi0  
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4581 find_call: = Found Their Call ID: 4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1 Their Tag a6f0ca54b388d36bi0 Our tag: as51ad4559
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:2210 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #85
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:2221 __sip_ack: Stopping retransmission on '4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1' of Request 103: Match Found
Really destroying SIP dialog '4c6fc5e8390e5a7f200a71e758f00da0@10.1.5.1' Method: INVITE
Really destroying SIP dialog '8AB6C795-7671-43EB-9F91-9286FE96C3C4@192.168.4.11' Method: BYE

<--- 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=z9hG4bKc0a8040b0000000b45d2bb0b00000cd300000036
Content-Length: 0
Call-ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11
CSeq: 7 OPTIONS
From: <sip:101@192.168.168.35:5060>;tag=845109519
Max-Forwards: 70
To: <sip:192.168.168.35:5060>

<------------->
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  0 [ 39]: OPTIONS sip:192.168.168.35:5060 SIP/2.0
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  1 [ 93]: Via: SIP/2.0/UDP 192.168.170.244;rport;branch=z9hG4bKc0a8040b0000000b45d2bb0b00000cd300000036
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  2 [ 17]: Content-Length: 0
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  3 [ 58]: Call-ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  4 [ 15]: CSeq: 7 OPTIONS
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  5 [ 49]: From: <sip:101@192.168.168.35:5060>;tag=845109519
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4795 parse_request:  Header  7 [ 29]: To: <sip:192.168.168.35:5060>
--- (8 headers 0 lines) ---
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4554 find_call: = Looking for  Call ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11 (Checking From) --From tag 845109519 --To-tag   
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11 Their Tag 82510925252 Our tag: as06bca392
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4581 find_call: = No match Their Call ID: a68d467a-1af0fdf@172.24.0.2 Their Tag e69107af299cb8e6o0 Our tag: as6b263dfe
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:4517 sip_alloc: Allocating new SIP dialog for E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11 - OPTIONS (No RTP)
[Feb 14 08:31:57] DEBUG[20527]: chan_sip.c:14892 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=z9hG4bKc0a8040b0000000b45d2bb0b00000cd300000036;received=192.168.170.244;rport=5060
From: <sip:101@192.168.168.35:5060>;tag=845109519
To: <sip:192.168.168.35:5060>;tag=as5afa7d0f
Call-ID: E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11
CSeq: 7 OPTIONS
User-Agent: Asterisk PBX SVN-trunk-r54149
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:192.168.168.35>
Accept: application/sdp
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11' in 32000 ms (Method: OPTIONS)
[Feb 14 08:31:59] DEBUG[20527]: chan_sip.c:2148 __sip_autodestruct: Auto destroying SIP dialog 'a68d467a-1af0fdf@172.24.0.2'
[Feb 14 08:31:59] DEBUG[20527]: chan_sip.c:3336 sip_destroy: Destroying SIP dialog a68d467a-1af0fdf@172.24.0.2
Really destroying SIP dialog 'a68d467a-1af0fdf@172.24.0.2' Method: REGISTER
stop no[Feb 14 08:32:09] DEBUG[20527]: chan_sip.c:2148 __sip_autodestruct: Auto destroying SIP dialog 'E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11'
[Feb 14 08:32:09] DEBUG[20527]: chan_sip.c:3336 sip_destroy: Destroying SIP dialog E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11
Really destroying SIP dialog 'E7BA4032-DFE5-49B2-B48A-D4E9F499FDE3@192.168.4.11' Method: OPTIONS
w