
<--- SIP read from 192.168.1.250:5060 --->
INVITE sip:1234@192.168.1.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-b2040a40;rport
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 101 INVITE
Max-Forwards: 70
Contact: Anonymous <sip:100089@192.168.1.250:5060>
Expires: 240
User-Agent: Linksys/PAP2T-3.1.15(LS)
Content-Length: 253
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura
Content-Type: application/sdp

v=0
o=- 10403 10403 IN IP4 192.168.1.250
s=-
c=IN IP4 192.168.1.250
t=0 0
m=audio 16438 RTP/AVP 8 100 101
a=rtpmap:8 PCMA/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

<------------->
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 0: INVITE sip:1234@192.168.1.10 SIP/2.0 (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-b2040a40;rport (65)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 2: From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0 (70)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 3: To: <sip:1234@192.168.1.10> (27)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 2edd173f-bc2d94ef@localhost (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 5: CSeq: 101 INVITE (16)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 7: Contact: Anonymous <sip:100089@192.168.1.250:5060> (56)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 8: Expires: 240 (12)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 9: User-Agent: Linksys/PAP2T-3.1.15(LS) (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 10: Content-Length: 253 (19)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 12: Supported: x-sipura (19)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 13: Content-Type: application/sdp (29)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 14:  (0)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: v=0 (3)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: o=- 10403 10403 IN IP4 192.168.1.250 (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: s=- (3)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.1.250 (22)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: t=0 0 (5)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: m=audio 16438 RTP/AVP 8 100 101 (31)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=rtpmap:100 NSE/8000 (21)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=fmtp:100 192-193 (18)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-15 (15)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=ptime:30 (10)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10)
--- (14 headers 13 lines) ---
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4562 find_call: = No match Their Call ID: 8d4f1bac-8e2cff29-b1c170c2@192.168.1.6 Their Tag 1DE11CC7-1D9CA748 Our tag: as21f7fc2f
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to Off
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 2edd173f-bc2d94ef@localhost - INVITE (With RTP)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:15153 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:1699 parse_sip_options: Begin: parsing SIP "Supported: x-sipura"
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:1707 parse_sip_options: Found SIP option: -x-sipura-
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:1719 parse_sip_options: Found private SIP option, not supported: x-sipura
Sending to 192.168.1.250 : 5060 (NAT)
Using INVITE request as basis request - 2edd173f-bc2d94ef@localhost
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On

<--- Reliably Transmitting (NAT) to 192.168.1.250:5060 --->
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-b2040a40;received=192.168.1.250;rport=5060
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>;tag=as758f5399
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 101 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1b36b50a"
Content-Length: 0


<------------>
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #52
Scheduling destruction of SIP dialog '2edd173f-bc2d94ef@localhost' in 32000 ms (Method: INVITE)
Found user '100089'

<--- SIP read from 192.168.1.250:5060 --->
ACK sip:1234@192.168.1.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-b2040a40;rport
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>;tag=as758f5399
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 101 ACK
Max-Forwards: 70
Contact: Anonymous <sip:100089@192.168.1.250:5060>
User-Agent: Linksys/PAP2T-3.1.15(LS)
Content-Length: 0


<------------->
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 0: ACK sip:1234@192.168.1.10 SIP/2.0 (33)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-b2040a40;rport (65)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 2: From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0 (70)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 3: To: <sip:1234@192.168.1.10>;tag=as758f5399 (42)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 2edd173f-bc2d94ef@localhost (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 5: CSeq: 101 ACK (13)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 7: Contact: Anonymous <sip:100089@192.168.1.250:5060> (56)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 8: User-Agent: Linksys/PAP2T-3.1.15(LS) (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 9: Content-Length: 0 (17)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 10:  (0)
--- (10 headers 0 lines) ---
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4562 find_call: = Found Their Call ID: 2edd173f-bc2d94ef@localhost Their Tag 5e47b2ffe97dac2fo0 Our tag: as758f5399
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:15153 handle_request: **** Received ACK (6) - Command in SIP ACK
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #52
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '2edd173f-bc2d94ef@localhost' of Response 101: Match Not Found

<--- SIP read from 192.168.1.250:5060 --->
INVITE sip:1234@192.168.1.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-59dd6e48;rport
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 102 INVITE
Max-Forwards: 70
Proxy-Authorization: Digest username="100089",realm="asterisk",nonce="1b36b50a",uri="sip:1234@192.168.1.10",algorithm=MD5,response="c25af8acccd8395fde48628aace562c9"
Contact: Anonymous <sip:100089@192.168.1.250:5060>
Expires: 240
User-Agent: Linksys/PAP2T-3.1.15(LS)
Content-Length: 253
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura
Content-Type: application/sdp

v=0
o=- 10403 10403 IN IP4 192.168.1.250
s=-
c=IN IP4 192.168.1.250
t=0 0
m=audio 16438 RTP/AVP 8 100 101
a=rtpmap:8 PCMA/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

<------------->
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 0: INVITE sip:1234@192.168.1.10 SIP/2.0 (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-59dd6e48;rport (65)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 2: From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0 (70)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 3: To: <sip:1234@192.168.1.10> (27)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 2edd173f-bc2d94ef@localhost (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 7: Proxy-Authorization: Digest username="100089",realm="asterisk",nonce="1b36b50a",uri="sip:1234@192.168.1.10",algorithm=MD5,response="c25af8acccd8395fde48628aace562c9" (171)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 8: Contact: Anonymous <sip:100089@192.168.1.250:5060> (56)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 9: Expires: 240 (12)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 10: User-Agent: Linksys/PAP2T-3.1.15(LS) (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 11: Content-Length: 253 (19)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 13: Supported: x-sipura (19)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 14: Content-Type: application/sdp (29)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 15:  (0)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: v=0 (3)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: o=- 10403 10403 IN IP4 192.168.1.250 (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: s=- (3)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.1.250 (22)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: t=0 0 (5)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: m=audio 16438 RTP/AVP 8 100 101 (31)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=rtpmap:100 NSE/8000 (21)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=fmtp:100 192-193 (18)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-15 (15)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=ptime:30 (10)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10)
--- (15 headers 13 lines) ---
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4562 find_call: = Found Their Call ID: 2edd173f-bc2d94ef@localhost Their Tag 5e47b2ffe97dac2fo0 Our tag: as758f5399
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:15153 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:1699 parse_sip_options: Begin: parsing SIP "Supported: x-sipura"
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:1707 parse_sip_options: Found SIP option: -x-sipura-
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:1719 parse_sip_options: Found private SIP option, not supported: x-sipura
Sending to 192.168.1.250 : 5060 (NAT)
Using INVITE request as basis request - 2edd173f-bc2d94ef@localhost
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On
Found user '100089'
Found RTP audio format 8
Found RTP audio format 100
Found RTP audio format 101
Peer audio RTP is at port 192.168.1.250:16438
Found audio description format PCMA for ID 8
Found unknown media description format NSE for ID 100
Got unsupported a:fmtp in SDP offer 
Found audio description format telephone-event for ID 101
Got unsupported a:fmtp in SDP offer 
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel <none>
Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw)
Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x1 (telephone-event), combined - 0x0 (nothing)
Peer audio RTP is at port 192.168.1.250:16438
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:13833 handle_request_invite: Checking SIP call limits for device 100089
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call
Looking for 1234 in internal (domain 192.168.1.10)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:3993 sip_new: *** Our native formats are 0x8 (alaw) 
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0x8 (alaw) 
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:3995 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4019 sip_new: This channel will not be able to handle video.
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:8245 build_route: build_route: Contact hop: Anonymous <sip:100089@192.168.1.250:5060>
list_route: hop: <sip:100089@192.168.1.250:5060>
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:13912 handle_request_invite: SIP/100089-08a13030: New call is still down.... Trying... 

<--- Transmitting (NAT) to 192.168.1.250:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-59dd6e48;received=192.168.1.250;rport=5060
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1234@192.168.1.10>
Content-Length: 0


<------------>
[Sep  3 20:00:58] DEBUG[8057]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100089-08a13030
[Sep  3 20:00:58] DEBUG[8084]: pbx.c:1827 pbx_extension_helper: Launching 'Answer'
    -- Executing [1234@internal:1] Answer("SIP/100089-08a13030", "") in new stack
[Sep  3 20:00:58] DEBUG[8084]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100089-08a13030
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:3647 sip_answer: SIP answering channel: SIP/100089-08a13030
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:6661 transmit_response_with_sdp: Setting framing from config on incoming call
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:6425 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:6426 add_sdp: ** Our prefcodec: 0x0 (nothing) 
Audio is at 192.168.1.10 port 10322
Adding codec 0x8 (alaw) to SDP
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:6557 add_sdp: -- Done with adding codecs to SDP
[Sep  3 20:00:58] DEBUG[8084]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:6602 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)

<--- Reliably Transmitting (NAT) to 192.168.1.250:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-59dd6e48;received=192.168.1.250;rport=5060
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>;tag=as45ac4ed5
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1234@192.168.1.10>
Content-Type: application/sdp
Content-Length: 182

v=0
o=root 8049 8049 IN IP4 192.168.1.10
s=session
c=IN IP4 192.168.1.10
t=0 0
m=audio 10322 RTP/AVP 8
a=rtpmap:8 PCMA/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Sep  3 20:00:58] DEBUG[8084]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #54
[Sep  3 20:00:58] DEBUG[8084]: pbx.c:1827 pbx_extension_helper: Launching 'VoiceMailMain'
    -- Executing [1234@internal:2] VoiceMailMain("SIP/100089-08a13030", "s1234") in new stack
[Sep  3 20:00:58] DEBUG[8084]: app_voicemail.c:6480 vm_execmain: After vm_authenticate
[Sep  3 20:00:58] DEBUG[8084]: app_voicemail.c:6514 vm_execmain: Before open_mailbox
[Sep  3 20:00:58] DEBUG[8055]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100089
[Sep  3 20:00:58] DEBUG[8055]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 100089
[Sep  3 20:00:58] DEBUG[8055]: devicestate.c:287 do_state_change: Changing state for SIP/100089 - state 1 (Not in use)
[Sep  3 20:00:58] DEBUG[8055]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100089
[Sep  3 20:00:58] DEBUG[8055]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 100089
[Sep  3 20:00:58] DEBUG[8055]: devicestate.c:287 do_state_change: Changing state for SIP/100089 - state 1 (Not in use)
[Sep  3 20:00:58] DEBUG[8080]: app_queue.c:581 handle_statechange: Device 'SIP/100089' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  3 20:00:58] DEBUG[8080]: app_queue.c:581 handle_statechange: Device 'SIP/100089' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

<--- SIP read from 192.168.1.250:5060 --->
ACK sip:1234@192.168.1.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-7ed98188;rport
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>;tag=as45ac4ed5
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 102 ACK
Max-Forwards: 70
Proxy-Authorization: Digest username="100089",realm="asterisk",nonce="1b36b50a",uri="sip:1234@192.168.1.10",algorithm=MD5,response="7f6ce3bf17058b5b6466a0ff676b2e8f"
Contact: Anonymous <sip:100089@192.168.1.250:5060>
User-Agent: Linksys/PAP2T-3.1.15(LS)
Content-Length: 0


<------------->
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 0: ACK sip:1234@192.168.1.10 SIP/2.0 (33)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-7ed98188;rport (65)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 2: From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0 (70)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 3: To: <sip:1234@192.168.1.10>;tag=as45ac4ed5 (42)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 2edd173f-bc2d94ef@localhost (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 ACK (13)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 7: Proxy-Authorization: Digest username="100089",realm="asterisk",nonce="1b36b50a",uri="sip:1234@192.168.1.10",algorithm=MD5,response="7f6ce3bf17058b5b6466a0ff676b2e8f" (171)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 8: Contact: Anonymous <sip:100089@192.168.1.250:5060> (56)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 9: User-Agent: Linksys/PAP2T-3.1.15(LS) (36)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 10: Content-Length: 0 (17)
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 11:  (0)
--- (11 headers 0 lines) ---
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:4562 find_call: = Found Their Call ID: 2edd173f-bc2d94ef@localhost Their Tag 5e47b2ffe97dac2fo0 Our tag: as45ac4ed5
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:15153 handle_request: **** Received ACK (6) - Command in SIP ACK
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #54
[Sep  3 20:00:58] DEBUG[8057]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '2edd173f-bc2d94ef@localhost' of Response 102: Match Not Found
[Sep  3 20:00:58] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app_voicemail.c:6520 vm_execmain: Number of old messages: 6
[Sep  3 20:00:58] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/INBOX'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/INBOX'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/INBOX'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/INBOX'
[Sep  3 20:00:58] DEBUG[8084]: app_voicemail.c:6527 vm_execmain: Number of new messages: 0
[Sep  3 20:00:58] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:00:58] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
[Sep  3 20:00:58] DEBUG[8084]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw
[Sep  3 20:00:58] DEBUG[8084]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
    -- <SIP/100089-08a13030> Playing 'vm-youhave' (language 'en')
[Sep  3 20:00:59] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:00:59] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
    -- <SIP/100089-08a13030> Playing 'digits/6' (language 'en')
[Sep  3 20:00:59] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:00:59] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
    -- <SIP/100089-08a13030> Playing 'vm-Old' (language 'en')
[Sep  3 20:01:00] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:01:00] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
    -- <SIP/100089-08a13030> Playing 'vm-messages' (language 'en')
[Sep  3 20:01:01] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:01:01] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
[Sep  3 20:01:01] DEBUG[8084]: rtp.c:2629 ast_rtp_raw_write: Difference is 688, ms is 106
    -- <SIP/100089-08a13030> Playing 'vm-onefor' (language 'en')
[Sep  3 20:01:02] DEBUG[8063]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem1
[Sep  3 20:01:02] NOTICE[8063]: chan_iax2.c:6027 update_registry: Restricting registration for peer 'iaxmodem1' to 60 seconds (requested 300)
[Sep  3 20:01:02] DEBUG[8055]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem1
[Sep  3 20:01:02] DEBUG[8055]: chan_iax2.c:10450 iax2_devicestate: Checking device state for device iaxmodem1
[Sep  3 20:01:02] DEBUG[8055]: chan_iax2.c:10458 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem1? addr=16777343, defaddr=0 maxms=0, lastms=0
[Sep  3 20:01:02] DEBUG[8055]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem1 - state 1 (Not in use)
[Sep  3 20:01:02] DEBUG[8080]: app_queue.c:581 handle_statechange: Device 'IAX2/iaxmodem1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  3 20:01:02] DEBUG[8065]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem
[Sep  3 20:01:02] DEBUG[8055]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem
[Sep  3 20:01:02] DEBUG[8055]: chan_iax2.c:10450 iax2_devicestate: Checking device state for device iaxmodem
[Sep  3 20:01:02] DEBUG[8055]: chan_iax2.c:10458 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem? addr=16777343, defaddr=0 maxms=0, lastms=0
[Sep  3 20:01:02] DEBUG[8055]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem - state 1 (Not in use)
[Sep  3 20:01:02] DEBUG[8080]: app_queue.c:581 handle_statechange: Device 'IAX2/iaxmodem' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  3 20:01:02] NOTICE[8065]: chan_iax2.c:6027 update_registry: Restricting registration for peer 'iaxmodem' to 60 seconds (requested 300)
[Sep  3 20:01:02] DEBUG[8066]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem2
[Sep  3 20:01:02] NOTICE[8066]: chan_iax2.c:6027 update_registry: Restricting registration for peer 'iaxmodem2' to 60 seconds (requested 300)
[Sep  3 20:01:02] DEBUG[8055]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem2
[Sep  3 20:01:02] DEBUG[8055]: chan_iax2.c:10450 iax2_devicestate: Checking device state for device iaxmodem2
[Sep  3 20:01:02] DEBUG[8055]: chan_iax2.c:10458 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem2? addr=16777343, defaddr=0 maxms=0, lastms=0
[Sep  3 20:01:02] DEBUG[8055]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem2 - state 1 (Not in use)
[Sep  3 20:01:02] DEBUG[8080]: app_queue.c:581 handle_statechange: Device 'IAX2/iaxmodem2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  3 20:01:02] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:01:02] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
    -- <SIP/100089-08a13030> Playing 'vm-Old' (language 'en')
[Sep  3 20:01:03] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:01:03] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
    -- <SIP/100089-08a13030> Playing 'vm-messages' (language 'en')
[Sep  3 20:01:04] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:01:04] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format gsm
    -- <SIP/100089-08a13030> Playing 'vm-opts' (language 'en')

<--- SIP read from 192.168.1.250:5060 --->
BYE sip:1234@192.168.1.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-16b0dfa;rport
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>;tag=as45ac4ed5
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 103 BYE
Max-Forwards: 70
Proxy-Authorization: Digest username="100089",realm="asterisk",nonce="1b36b50a",uri="sip:1234@192.168.1.10",algorithm=MD5,response="b09cf86afcf7f61615d737916ed2db91"
User-Agent: Linksys/PAP2T-3.1.15(LS)
Content-Length: 0


<------------->
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 0: BYE sip:1234@192.168.1.10 SIP/2.0 (33)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-16b0dfa;rport (64)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 2: From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0 (70)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 3: To: <sip:1234@192.168.1.10>;tag=as45ac4ed5 (42)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 2edd173f-bc2d94ef@localhost (36)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 5: CSeq: 103 BYE (13)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 7: Proxy-Authorization: Digest username="100089",realm="asterisk",nonce="1b36b50a",uri="sip:1234@192.168.1.10",algorithm=MD5,response="b09cf86afcf7f61615d737916ed2db91" (171)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 8: User-Agent: Linksys/PAP2T-3.1.15(LS) (36)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 9: Content-Length: 0 (17)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4774 parse_request: Header 10:  (0)
--- (10 headers 0 lines) ---
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:4562 find_call: = Found Their Call ID: 2edd173f-bc2d94ef@localhost Their Tag 5e47b2ffe97dac2fo0 Our tag: as45ac4ed5
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:15153 handle_request: **** Received BYE (8) - Command in SIP BYE
Sending to 192.168.1.250 : 5060 (NAT)
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2edd173f-bc2d94ef@localhost
[Sep  3 20:01:09] DEBUG[8057]: chan_sip.c:14705 handle_request_bye: Received bye, issuing owner hangup

<--- Transmitting (NAT) to 192.168.1.250:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.250:5060;branch=z9hG4bK-16b0dfa;received=192.168.1.250;rport=5060
From: Anonymous <sip:100089@192.168.1.10>;tag=5e47b2ffe97dac2fo0
To: <sip:1234@192.168.1.10>;tag=as45ac4ed5
Call-ID: 2edd173f-bc2d94ef@localhost
CSeq: 103 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1234@192.168.1.10>
Content-Length: 0


<------------>
[Sep  3 20:01:09] DEBUG[8084]: channel.c:3066 set_format: Set channel SIP/100089-08a13030 to write format alaw
[Sep  3 20:01:09] DEBUG[8084]: app.c:1022 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:01:09] DEBUG[8084]: app.c:1043 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/1234/Old'
[Sep  3 20:01:09] DEBUG[8084]: pbx.c:2425 __ast_pbx_run: Spawn extension (internal,1234,2) exited non-zero on 'SIP/100089-08a13030'
  == Spawn extension (internal, 1234, 2) exited non-zero on 'SIP/100089-08a13030'
[Sep  3 20:01:09] DEBUG[8084]: channel.c:1567 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/100089-08a13030'
[Sep  3 20:01:09] DEBUG[8084]: channel.c:1786 ast_hangup: Hanging up channel 'SIP/100089-08a13030'
[Sep  3 20:01:09] DEBUG[8084]: chan_sip.c:3485 sip_hangup: Hangup call SIP/100089-08a13030, SIP callid 2edd173f-bc2d94ef@localhost)
[Sep  3 20:01:09] DEBUG[8084]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100089-08a13030
[Sep  3 20:01:09] DEBUG[8055]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100089
[Sep  3 20:01:09] DEBUG[8055]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 100089
[Sep  3 20:01:09] DEBUG[8055]: devicestate.c:287 do_state_change: Changing state for SIP/100089 - state 1 (Not in use)
[Sep  3 20:01:09] DEBUG[8080]: app_queue.c:581 handle_statechange: Device 'SIP/100089' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Really destroying SIP dialog '2edd173f-bc2d94ef@localhost' Method: BYE
[Sep  3 20:01:09] DEBUG[8084]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded!