
<--- SIP read from 1.2.3.4:5060 --->
INVITE sip:066504321@202.137.240.89:5060 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-113c-1189031789-11403-181
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 1 INVITE
Max-Forwards: 70
To: <sip:066504321@202.137.240.89:5060>
From: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
User-Agent: Cantata-SIP/10.3.2.217 NAP1-6650 1
Timestamp: 09052007223629
P-Asserted-Identity: 21642764<sip:21642764@202.137.240.83>
Privacy: id
Contact: <sip:anonymous@202.137.240.83:5060>
Allow: INVITE, BYE, REGISTER, ACK, OPTIONS, CANCEL, INFO
Supported: path
Expires: 300
Organization: Cantata Technology Inc
Remote-Party-ID: 21642764<sip:21642764@202.137.240.83;user=phone>;party=calling;id-type=subscriber;privacy=full;screen=yes
Content-Type: application/sdp
Content-Length: 249

v=0
o=Cantata_SDP 0 0 IN IP4 202.137.240.83
s=Cantata-SIP
c=IN IP4 202.137.240.82
t=0 0
m=audio 10624 RTP/AVP 18 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -

<------------->
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:066504321@202.137.240.89:5060 SIP/2.0 (48)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-113c-1189031789-11403-181 (83)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: CSeq: 1 INVITE (14)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: Max-Forwards: 70 (16)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: To: <sip:066504321@202.137.240.89:5060> (39)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: From: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (114)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Cantata-SIP/10.3.2.217 NAP1-6650 1 (46)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Timestamp: 09052007223629 (25)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: P-Asserted-Identity: 21642764<sip:21642764@202.137.240.83> (58)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Privacy: id (11)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11: Contact: <sip:anonymous@202.137.240.83:5060> (44)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 12: Allow: INVITE, BYE, REGISTER, ACK, OPTIONS, CANCEL, INFO (56)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 13: Supported: path (15)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 14: Expires: 300 (12)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 15: Organization: Cantata Technology Inc (36)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 16: Remote-Party-ID: 21642764<sip:21642764@202.137.240.83;user=phone>;party=calling;id-type=subscriber;privacy=full;screen=yes (122)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 17: Content-Type: application/sdp (29)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 18: Content-Length: 249 (19)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 19:  (0)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: o=Cantata_SDP 0 0 IN IP4 202.137.240.83 (39)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: s=Cantata-SIP (13)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: c=IN IP4 202.137.240.82 (23)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: m=audio 10624 RTP/AVP 18 0 101 (30)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:18 G729/8000 (21)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=silenceSupp:off - - - - (25)
[Sep  6 10:29:40] --- (19 headers 11 lines) ---
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:2705 do_setnat: Setting NAT on UDPTL to Off
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 - INVITE (With RTP)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:14944 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:1693 parse_sip_options: Begin: parsing SIP "Supported: path"
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:1701 parse_sip_options: Found SIP option: -path-
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:1707 parse_sip_options: Matched SIP option: path
[Sep  6 10:29:40] Sending to 1.2.3.4 : 5060 (NAT)
[Sep  6 10:29:40] Using INVITE request as basis request - 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:40] Found peer 'imgnap1-modem'
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:2705 do_setnat: Setting NAT on UDPTL to Off
[Sep  6 10:29:40] Found RTP audio format 18
[Sep  6 10:29:40] Found RTP audio format 0
[Sep  6 10:29:40] Found RTP audio format 101
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:5068 process_sdp: Peer doesn't provide T.38 UDPTL
[Sep  6 10:29:40] Peer audio RTP is at port 202.137.240.82:10624
[Sep  6 10:29:40] Found description format PCMU for ID 0
[Sep  6 10:29:40] Found description format G729 for ID 18
[Sep  6 10:29:40] Found description format telephone-event for ID 101
[Sep  6 10:29:40] Got unsupported a:fmtp in SDP offer 
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:5301 process_sdp: T38 state changed to 0 on channel <none>
[Sep  6 10:29:40] Capabilities: us - 0x4 (ulaw), peer - audio=0x104 (ulaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Sep  6 10:29:40] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Sep  6 10:29:40] Peer audio RTP is at port 202.137.240.82:10624
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:5381 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:13626 handle_request_invite: Checking SIP call limits for device 
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call
[Sep  6 10:29:40] Looking for 066504321 in napier (domain 202.137.240.89)
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:3944 sip_new: *** Our native formats are 0x4 (ulaw) 
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:3945 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:3946 sip_new: *** Our capabilities are 0x4 (ulaw) 
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:3947 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:3970 sip_new: This channel will not be able to handle video.
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:8140 build_route: build_route: Contact hop: <sip:anonymous@202.137.240.83:5060>
[Sep  6 10:29:40] list_route: hop: <sip:anonymous@202.137.240.83:5060>
[Sep  6 10:29:40] DEBUG[3020]: chan_sip.c:13701 handle_request_invite: SIP/anonymous.invalid-0821af30: New call is still down.... Trying... 
[Sep  6 10:29:40] 
<--- Transmitting (no NAT) to 202.137.240.83:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-113c-1189031789-11403-181;received=1.2.3.4
From: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
To: <sip:066504321@202.137.240.89:5060>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:066504321@202.137.240.89>
Content-Length: 0


<------------>
[Sep  6 10:29:40] DEBUG[3020]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/anonymous.invalid-0821af30
[Sep  6 10:29:40] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - anonymous.invalid
[Sep  6 10:29:40] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer anonymous.invalid
[Sep  6 10:29:40] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Goto'
[Sep  6 10:29:40]     -- Executing [066504321@napier:1] Goto("SIP/anonymous.invalid-0821af30", "airnetmainivr|s|1") in new stack
[Sep  6 10:29:40]     -- Goto (airnetmainivr,s,1)
[Sep  6 10:29:40] DEBUG[3077]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Sep  6 10:29:40] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'ExecIf'
[Sep  6 10:29:40]     -- Executing [s@airnetmainivr:1] ExecIf("SIP/anonymous.invalid-0821af30", "0|Gosub|globalsubroutines|remoteheaders|1") in new stack
[Sep  6 10:29:40] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Ringing'
[Sep  6 10:29:40]     -- Executing [s@airnetmainivr:2] Ringing("SIP/anonymous.invalid-0821af30", "") in new stack
[Sep  6 10:29:40] 
<--- Transmitting (no NAT) to 202.137.240.83:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-113c-1189031789-11403-181;received=1.2.3.4
From: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:066504321@202.137.240.89>
Content-Length: 0


<------------>
[Sep  6 10:29:40] DEBUG[3077]: channel.c:2597 ast_indicate_data: Driver for channel 'SIP/anonymous.invalid-0821af30' does not support indication 3, emulating it
[Sep  6 10:29:40] DEBUG[3077]: channel.c:2748 ast_prod: Prodding channel 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:40] DEBUG[3077]: chan_sip.c:6574 transmit_response_with_sdp: Setting framing from config on incoming call
[Sep  6 10:29:40] DEBUG[3077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Sep  6 10:29:40] DEBUG[3077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Sep  6 10:29:40] Audio is at 202.137.240.89 port 15408
[Sep  6 10:29:40] Adding codec 0x4 (ulaw) to SDP
[Sep  6 10:29:40] Adding non-codec 0x1 (telephone-event) to SDP
[Sep  6 10:29:40] DEBUG[3077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP
[Sep  6 10:29:40] DEBUG[3077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Sep  6 10:29:40] 
<--- Transmitting (no NAT) to 202.137.240.83:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-113c-1189031789-11403-181;received=1.2.3.4
From: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:066504321@202.137.240.89>
Content-Type: application/sdp
Content-Length: 215

v=0
o=root 2989 2989 IN IP4 202.137.240.89
s=session
c=IN IP4 202.137.240.89
t=0 0
m=audio 15408 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[Sep  6 10:29:40] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/anonymous.invalid-0821af30 to write format slin
[Sep  6 10:29:40] DEBUG[3077]: channel.c:2072 ast_settimeout: Scheduling timer at 160 sample intervals
[Sep  6 10:29:40] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Wait'
[Sep  6 10:29:40]     -- Executing [s@airnetmainivr:3] Wait("SIP/anonymous.invalid-0821af30", "3") in new stack
[Sep  6 10:29:40] DEBUG[3077]: rtp.c:2727 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Sep  6 10:29:40] DEBUG[3077]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Sep  6 10:29:40] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/anonymous.invalid - state 4 (Invalid)
[Sep  6 10:29:40] DEBUG[3078]: app_queue.c:548 changethread: Device 'SIP/anonymous.invalid' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Sep  6 10:29:43] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Answer'
[Sep  6 10:29:43]     -- Executing [s@airnetmainivr:4] Answer("SIP/anonymous.invalid-0821af30", "") in new stack
[Sep  6 10:29:43] DEBUG[3077]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/anonymous.invalid-0821af30
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:3602 sip_answer: SIP answering channel: SIP/anonymous.invalid-0821af30
[Sep  6 10:29:43] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - anonymous.invalid
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:6574 transmit_response_with_sdp: Setting framing from config on incoming call
[Sep  6 10:29:43] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer anonymous.invalid
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Sep  6 10:29:43] Audio is at 202.137.240.89 port 15408
[Sep  6 10:29:43] Adding codec 0x4 (ulaw) to SDP
[Sep  6 10:29:43] Adding non-codec 0x1 (telephone-event) to SDP
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Sep  6 10:29:43] 
<--- Reliably Transmitting (no NAT) to 202.137.240.83:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-113c-1189031789-11403-181;received=1.2.3.4
From: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:066504321@202.137.240.89>
Content-Type: application/sdp
Content-Length: 215

v=0
o=root 2989 2990 IN IP4 202.137.240.89
s=session
c=IN IP4 202.137.240.89
t=0 0
m=audio 15408 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[Sep  6 10:29:43] DEBUG[3077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep  6 10:29:43] DEBUG[3077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #105
[Sep  6 10:29:43] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
[Sep  6 10:29:43]     -- Executing [s@airnetmainivr:5] Set("SIP/anonymous.invalid-0821af30", "TIMEOUT(digit)=5") in new stack
[Sep  6 10:29:43]     -- Digit timeout set to 5
[Sep  6 10:29:43] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'BackGround'
[Sep  6 10:29:43]     -- Executing [s@airnetmainivr:6] BackGround("SIP/anonymous.invalid-0821af30", "customivr/airnet-mainivr") in new stack
[Sep  6 10:29:43] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/anonymous.invalid-0821af30 to write format ulaw
[Sep  6 10:29:43] DEBUG[3077]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Sep  6 10:29:43] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/anonymous.invalid-0821af30 to write format slin
[Sep  6 10:29:43] DEBUG[3077]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Sep  6 10:29:43] DEBUG[3077]: channel.c:2072 ast_settimeout: Scheduling timer at 160 sample intervals
[Sep  6 10:29:43]     -- <SIP/anonymous.invalid-0821af30> Playing 'customivr/airnet-mainivr' (language 'en')
[Sep  6 10:29:43] DEBUG[3077]: rtp.c:2597 ast_rtp_raw_write: Difference is 160, ms is 0
[Sep  6 10:29:43] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/anonymous.invalid - state 4 (Invalid)
[Sep  6 10:29:43] DEBUG[3079]: app_queue.c:548 changethread: Device 'SIP/anonymous.invalid' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Sep  6 10:29:43] 
<--- SIP read from 1.2.3.4:5060 --->
ACK sip:066504321@202.137.240.89 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-644e-1189031793-11403-181
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 1 ACK
Max-Forwards: 70
To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
From: <sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
User-Agent: Cantata-SIP/10.3.2.217 NAP1-6650 1
Content-Length: 0


<------------->
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: ACK sip:066504321@202.137.240.89 SIP/2.0 (40)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-644e-1189031793-11403-181 (83)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: CSeq: 1 ACK (11)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: Max-Forwards: 70 (16)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (54)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: From: <sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (105)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Cantata-SIP/10.3.2.217 NAP1-6650 1 (46)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Content-Length: 0 (17)
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9:  (0)
[Sep  6 10:29:43] --- (9 headers 0 lines) ---
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:14944 handle_request: **** Received ACK (6) - Command in SIP ACK
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #105
[Sep  6 10:29:43] DEBUG[3020]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' of Response 1: Match Not Found
[Sep  6 10:29:45] 
<--- SIP read from 10.10.1.245:5060 --->
REGISTER sip:voip-nap2.airnet.net.nz SIP/2.0
Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bK428550d42921F7B7
From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F
To: <sip:66500504@voip-nap2.airnet.net.nz>
CSeq: 41 REGISTER
Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245
Contact: <sip:66500504@10.10.1.245>;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER"
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708
Authorization: Digest username="66500504", realm="asterisk", nonce="122802a0", uri="sip:voip-nap2.airnet.net.nz", response="7e9bc6e4f36b6c0e02f7a62f61bd7889", algorithm=MD5
Max-Forwards: 70
Expires: 120
Content-Length: 0


<------------->
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: REGISTER sip:voip-nap2.airnet.net.nz SIP/2.0 (44)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bK428550d42921F7B7 (59)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F (77)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@voip-nap2.airnet.net.nz> (42)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: CSeq: 41 REGISTER (17)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245 (47)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Contact: <sip:66500504@10.10.1.245>;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER" (135)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708 (54)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Authorization: Digest username="66500504", realm="asterisk", nonce="122802a0", uri="sip:voip-nap2.airnet.net.nz", response="7e9bc6e4f36b6c0e02f7a62f61bd7889", algorithm=MD5 (172)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Max-Forwards: 70 (16)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Expires: 120 (12)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11: Content-Length: 0 (17)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 12:  (0)
[Sep  6 10:29:45] --- (12 headers 0 lines) ---
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for af510e32-75a4b30c-86d5f2fd@10.10.1.245 - REGISTER (No RTP)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:14944 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
[Sep  6 10:29:45] Using latest REGISTER request as basis request
[Sep  6 10:29:45] Sending to 10.10.1.245 : 5060 (no NAT)
[Sep  6 10:29:45] 
<--- Transmitting (no NAT) to 10.10.1.245:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bK428550d42921F7B7;received=10.10.1.245
From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F
To: <sip:66500504@voip-nap2.airnet.net.nz>
Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245
CSeq: 41 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:66500504@202.137.240.89>
Content-Length: 0


<------------>
[Sep  6 10:29:45] 
<--- Transmitting (no NAT) to 10.10.1.245:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bK428550d42921F7B7;received=10.10.1.245
From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F
To: <sip:66500504@voip-nap2.airnet.net.nz>;tag=as3cbe987f
Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245
CSeq: 41 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="622c7fcf"
Content-Length: 0


<------------>
[Sep  6 10:29:45] Scheduling destruction of SIP dialog 'af510e32-75a4b30c-86d5f2fd@10.10.1.245' in 32000 ms (Method: REGISTER)
[Sep  6 10:29:45] DEBUG[3077]: rtp.c:875 ast_rtcp_read: Got RTCP report of 88 bytes
[Sep  6 10:29:45] 
<--- SIP read from 10.10.1.245:5060 --->
REGISTER sip:voip-nap2.airnet.net.nz SIP/2.0
Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bKe47650fe3339E659
From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F
To: <sip:66500504@voip-nap2.airnet.net.nz>
CSeq: 42 REGISTER
Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245
Contact: <sip:66500504@10.10.1.245>;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER"
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708
Authorization: Digest username="66500504", realm="asterisk", nonce="622c7fcf", uri="sip:voip-nap2.airnet.net.nz", response="2d0ac1da7b8336f94b112ef6e711a595", algorithm=MD5
Max-Forwards: 70
Expires: 120
Content-Length: 0


<------------->
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: REGISTER sip:voip-nap2.airnet.net.nz SIP/2.0 (44)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bKe47650fe3339E659 (59)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F (77)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@voip-nap2.airnet.net.nz> (42)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: CSeq: 42 REGISTER (17)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245 (47)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Contact: <sip:66500504@10.10.1.245>;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER" (135)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708 (54)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Authorization: Digest username="66500504", realm="asterisk", nonce="622c7fcf", uri="sip:voip-nap2.airnet.net.nz", response="2d0ac1da7b8336f94b112ef6e711a595", algorithm=MD5 (172)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Max-Forwards: 70 (16)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Expires: 120 (12)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11: Content-Length: 0 (17)
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 12:  (0)
[Sep  6 10:29:45] --- (12 headers 0 lines) ---
[Sep  6 10:29:45] DEBUG[3020]: chan_sip.c:14944 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
[Sep  6 10:29:45] Using latest REGISTER request as basis request
[Sep  6 10:29:45] Sending to 10.10.1.245 : 5060 (no NAT)
[Sep  6 10:29:45] 
<--- Transmitting (no NAT) to 10.10.1.245:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bKe47650fe3339E659;received=10.10.1.245
From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F
To: <sip:66500504@voip-nap2.airnet.net.nz>
Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245
CSeq: 42 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:66500504@202.137.240.89>
Content-Length: 0


<------------>
[Sep  6 10:29:45]     -- Saved useragent "PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708" for peer 66500504
[Sep  6 10:29:45] 
<--- Transmitting (no NAT) to 10.10.1.245:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.10.1.245;branch=z9hG4bKe47650fe3339E659;received=10.10.1.245
From: "Sam Desk" <sip:66500504@voip-nap2.airnet.net.nz>;tag=7ABC03F6-45705A8F
To: <sip:66500504@voip-nap2.airnet.net.nz>;tag=as3cbe987f
Call-ID: af510e32-75a4b30c-86d5f2fd@10.10.1.245
CSeq: 42 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 120
Contact: <sip:66500504@10.10.1.245>;expires=120
Date: Wed, 05 Sep 2007 22:29:45 GMT
Content-Length: 0


<------------>
[Sep  6 10:29:45] DEBUG[3020]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504
[Sep  6 10:29:45] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:45] Scheduling destruction of SIP dialog 'af510e32-75a4b30c-86d5f2fd@10.10.1.245' in 32000 ms (Method: REGISTER)
[Sep  6 10:29:45] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:45] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 1 (Not in use)
[Sep  6 10:29:45] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:45] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:45] DEBUG[3081]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at 202.137.240.82
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at 202.137.240.82
[Sep  6 10:29:48] DEBUG[3077]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/anonymous.invalid-0821af30 to write format ulaw
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:2392 __ast_pbx_run: Oooh, got something to jump out with ('3')!
[Sep  6 10:29:48]   == CDR updated on SIP/anonymous.invalid-0821af30
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIfTime'
[Sep  6 10:29:48]     -- Executing [3@airnetmainivr:1] GotoIfTime("SIP/anonymous.invalid-0821af30", "08:30-17:30|mon-fri|*|*?airnetmainivr|3|7") in new stack
[Sep  6 10:29:48]     -- Goto (airnetmainivr,3,7)
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'anonymous'
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
[Sep  6 10:29:48]     -- Executing [3@airnetmainivr:7] Set("SIP/anonymous.invalid-0821af30", "CALLERID(name)="T anonymous"") in new stack
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is ''
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
[Sep  6 10:29:48]     -- Executing [3@airnetmainivr:8] Set("SIP/anonymous.invalid-0821af30", "CDR(userfield)=VPBXIVRMenu:3-Support>") in new stack
[Sep  6 10:29:48] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Dial'
[Sep  6 10:29:48]     -- Executing [3@airnetmainivr:9] Dial("SIP/anonymous.invalid-0821af30", "SIP/66500503&SIP/66500504&SIP/66500506&SIP/66500512&SIP/66500562&SIP/66500553|10|t") in new stack
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Sep  6 10:29:48] WARNING[3077]: chan_sip.c:2860 create_addr: No such host: 66500503
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15672 sip_request_call: Cant create SIP call - target device not registred
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 793b32bc17df259205d4e5067bacb097@127.0.0.1
[Sep  6 10:29:48] Really destroying SIP dialog '793b32bc17df259205d4e5067bacb097@127.0.0.1' Method: INVITE
[Sep  6 10:29:48] WARNING[3077]: app_dial.c:1106 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2741 create_addr_from_peer: Our T38 capability (3856)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2705 do_setnat: Setting NAT on UDPTL to Off
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3944 sip_new: *** Our native formats are 0x100 (g729) 
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3945 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3946 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3947 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3949 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3970 sip_new: This channel will not be able to handle video.
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:1621 ast_rtp_make_compatible: Seeded SDP of 'SIP/66500504-082596b8' with that of 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-3-9.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-3-8.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-3-7.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-3-1.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-s-6.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-s-5.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-s-4.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-s-3.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-s-2.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-airnetmainivr-s-1.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable STACK-napier-066504321-1.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3514 ast_channel_inherit_variables: Not copying variable SIPURI.
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2953 sip_call: Outgoing Call for 66500504
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3210 update_call_counter: Call to peer '66500504' is 1 out of 1
[Sep  6 10:29:48] DEBUG[3077]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504
[Sep  6 10:29:48] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:48] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:48] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 6 (Ringing)
[Sep  6 10:29:48] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2968 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: False
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Sep  6 10:29:48] Audio is at 202.137.240.89 port 12676
[Sep  6 10:29:48] Adding codec 0x4 (ulaw) to SDP
[Sep  6 10:29:48] Adding codec 0x100 (g729) to SDP
[Sep  6 10:29:48] Adding non-codec 0x1 (telephone-event) to SDP
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x104 (ulaw|g729)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:66500504@10.10.1.245 SIP/2.0 (39)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f (59)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 2: From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105 (65)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@10.10.1.245> (30)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 4: Contact: <sip:anonymous@202.137.240.89> (39)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89 (56)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 INVITE (16)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 9: Remote-Party-ID: "T anonymous" <sip:anonymous@202.137.240.89>;privacy=full;screen=no (84)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 10: Date: Wed, 05 Sep 2007 22:29:48 GMT (35)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 12: Supported: replaces (19)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 13: Content-Type: application/sdp (29)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 14: Content-Length: 262 (19)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 15:  (0)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: o=root 2989 2989 IN IP4 202.137.240.89 (38)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: s=session (9)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: c=IN IP4 202.137.240.89 (23)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: m=audio 12676 RTP/AVP 0 18 101 (30)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:18 G729/8000 (21)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=fmtp:18 annexb=no (19)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-16 (15)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10)
[Sep  6 10:29:48] Reliably Transmitting (no NAT) to 10.10.1.245:5060:
INVITE sip:66500504@10.10.1.245 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>
Contact: <sip:anonymous@202.137.240.89>
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Remote-Party-ID: "T anonymous" <sip:anonymous@202.137.240.89>;privacy=full;screen=no
Date: Wed, 05 Sep 2007 22:29:48 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 262

v=0
o=root 2989 2989 IN IP4 202.137.240.89
s=session
c=IN IP4 202.137.240.89
t=0 0
m=audio 12676 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Sep  6 10:29:48] DEBUG[3077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #109
[Sep  6 10:29:48]     -- Called 66500504
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3082]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Sep  6 10:29:48] WARNING[3077]: chan_sip.c:2860 create_addr: No such host: 66500506
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15672 sip_request_call: Cant create SIP call - target device not registred
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 5052a2414dd1b7ac70bd1ac83963d1b9@127.0.0.1
[Sep  6 10:29:48] Really destroying SIP dialog '5052a2414dd1b7ac70bd1ac83963d1b9@127.0.0.1' Method: INVITE
[Sep  6 10:29:48] WARNING[3077]: app_dial.c:1106 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Sep  6 10:29:48] WARNING[3077]: chan_sip.c:2860 create_addr: No such host: 66500512
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15672 sip_request_call: Cant create SIP call - target device not registred
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 7347f4744fb14dfa606586c25a9b85d2@127.0.0.1
[Sep  6 10:29:48] Really destroying SIP dialog '7347f4744fb14dfa606586c25a9b85d2@127.0.0.1' Method: INVITE
[Sep  6 10:29:48] WARNING[3077]: app_dial.c:1106 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Sep  6 10:29:48] WARNING[3077]: chan_sip.c:2860 create_addr: No such host: 66500562
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15672 sip_request_call: Cant create SIP call - target device not registred
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 0db695ae4e90a6bf201079722daff58a@127.0.0.1
[Sep  6 10:29:48] Really destroying SIP dialog '0db695ae4e90a6bf201079722daff58a@127.0.0.1' Method: INVITE
[Sep  6 10:29:48] WARNING[3077]: app_dial.c:1106 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Sep  6 10:29:48] WARNING[3077]: chan_sip.c:2860 create_addr: No such host: 66500553
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:15672 sip_request_call: Cant create SIP call - target device not registred
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 5735178a22a67f79720d83216b48b5dd@127.0.0.1
[Sep  6 10:29:48] Really destroying SIP dialog '5735178a22a67f79720d83216b48b5dd@127.0.0.1' Method: INVITE
[Sep  6 10:29:48] WARNING[3077]: app_dial.c:1106 dial_exec_full: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/66500504-082596b8 to read format slin
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/anonymous.invalid-0821af30 to write format slin
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/anonymous.invalid-0821af30 to read format slin
[Sep  6 10:29:48] DEBUG[3077]: channel.c:3020 set_format: Set channel SIP/66500504-082596b8 to write format slin
[Sep  6 10:29:48] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[Sep  6 10:29:48] 
<--- SIP read from 10.10.1.245:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B
CSeq: 102 INVITE
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
Contact: <sip:66500504@10.10.1.245>
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708
Content-Length: 0


<------------->
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 100 Trying (18)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f (59)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105 (65)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B (52)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: CSeq: 102 INVITE (16)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89 (56)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Contact: <sip:66500504@10.10.1.245> (35)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708 (54)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Content-Length: 0 (17)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9:  (0)
[Sep  6 10:29:48] --- (9 headers 0 lines) ---
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2191 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #109 - INVITE (got response)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1e81bc92200f708b3bcb19484f3adac8@202.137.240.89' Request 102: Found
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:11814 handle_response_invite: SIP response 100 to standard invite
[Sep  6 10:29:48] 
<--- SIP read from 10.10.1.245:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B
CSeq: 102 INVITE
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
Contact: <sip:66500504@10.10.1.245>
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708
Allow-Events: talk,hold,conference
Content-Length: 0


<------------->
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 180 Ringing (19)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f (59)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105 (65)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B (52)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: CSeq: 102 INVITE (16)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89 (56)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Contact: <sip:66500504@10.10.1.245> (35)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708 (54)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Allow-Events: talk,hold,conference (34)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10:  (0)
[Sep  6 10:29:48] --- (10 headers 0 lines) ---
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1e81bc92200f708b3bcb19484f3adac8@202.137.240.89' Request 102: Found
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:11814 handle_response_invite: SIP response 180 to standard invite
[Sep  6 10:29:48] DEBUG[3020]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504-082596b8
[Sep  6 10:29:48] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:48] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:48] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 6 (Ringing)
[Sep  6 10:29:48] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:48] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:48]     -- SIP/66500504-082596b8 is ringing
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:17253 sip_set_rtp_peer: Sending reinvite on SIP '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' - It's audio soon redirected to IP 202.137.240.89
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:5788 reqprep: Strict routing enforced for session 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:48] set_destination: Parsing <sip:anonymous@202.137.240.83:5060> for address/port to send to
[Sep  6 10:29:48] set_destination: set destination to 202.137.240.83, port 5060
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Sep  6 10:29:48] Audio is at 202.137.240.89 port 15408
[Sep  6 10:29:48] Adding codec 0x4 (ulaw) to SDP
[Sep  6 10:29:48] Adding non-codec 0x1 (telephone-event) to SDP
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:1634 initialize_initreq: Initializing already initialized SIP dialog 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (presumably reinvite)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:anonymous@202.137.240.83:5060 SIP/2.0 (48)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK7912247f (59)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 2: From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (56)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 3: To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (112)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 4: Contact: <sip:066504321@202.137.240.89> (39)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 INVITE (16)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 10: Supported: replaces (19)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 12: Content-Type: application/sdp (29)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 13: Content-Length: 215 (19)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 14:  (0)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: o=root 2989 2991 IN IP4 202.137.240.89 (38)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: s=session (9)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: c=IN IP4 202.137.240.89 (23)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: m=audio 15408 RTP/AVP 0 101 (27)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-16 (15)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10)
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10)
[Sep  6 10:29:48] Reliably Transmitting (no NAT) to 202.137.240.83:5060:
INVITE sip:anonymous@202.137.240.83:5060 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK7912247f
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
Contact: <sip:066504321@202.137.240.89>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 215

v=0
o=root 2989 2991 IN IP4 202.137.240.89
s=session
c=IN IP4 202.137.240.89
t=0 0
m=audio 15408 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Sep  6 10:29:48] DEBUG[3077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep  6 10:29:48] DEBUG[3077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #111
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:1550 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/anonymous.invalid-0821af30' with that of 'SIP/66500504-082596b8'
[Sep  6 10:29:48] DEBUG[3077]: channel.c:2597 ast_indicate_data: Driver for channel 'SIP/anonymous.invalid-0821af30' does not support indication 3, emulating it
[Sep  6 10:29:48] DEBUG[3077]: channel.c:2072 ast_settimeout: Scheduling timer at 160 sample intervals
[Sep  6 10:29:48] DEBUG[3083]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Sep  6 10:29:48] 
<--- SIP read from 1.2.3.4:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK7912247f;received=202.137.240.89
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
CSeq: 102 INVITE
Server: Cantata-SIP/10.3.2.217 NAP1-6650 1
Content-Length: 0


<------------->
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 100 Trying (18)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK7912247f;received=202.137.240.89 (83)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (56)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (112)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 INVITE (16)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Server: Cantata-SIP/10.3.2.217 NAP1-6650 1 (42)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: Content-Length: 0 (17)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8:  (0)
[Sep  6 10:29:48] --- (8 headers 0 lines) ---
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2191 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #111 - INVITE (got response)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' Request 102: Found
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:11812 handle_response_invite: SIP response 100 to RE-invite on outgoing call 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:48] 
<--- SIP read from 1.2.3.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK7912247f;received=202.137.240.89
Contact: <sip:anonymous@202.137.240.83:5060>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
CSeq: 102 INVITE
Server: Cantata-SIP/10.3.2.217 NAP1-6650 1
Allow: INVITE, BYE, REGISTER, ACK, OPTIONS, CANCEL, INFO
Supported: path
Accept: application/sdp
Content-Type: application/sdp
Content-Length: 235

v=0
o=Cantata_SDP 0 1 IN IP4 202.137.240.83
s=Cantata-SIP
c=IN IP4 202.137.240.82
t=0 0
m=audio 10624 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20

<------------->
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK7912247f;received=202.137.240.89 (83)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Contact: <sip:anonymous@202.137.240.83:5060> (44)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (56)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (112)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 INVITE (16)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: Server: Cantata-SIP/10.3.2.217 NAP1-6650 1 (42)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Allow: INVITE, BYE, REGISTER, ACK, OPTIONS, CANCEL, INFO (56)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Supported: path (15)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Accept: application/sdp (23)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11: Content-Type: application/sdp (29)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 235 (19)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 13:  (0)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: o=Cantata_SDP 0 1 IN IP4 202.137.240.83 (39)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: s=Cantata-SIP (13)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: c=IN IP4 202.137.240.82 (23)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: m=audio 10624 RTP/AVP 0 101 (27)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=silenceSupp:off - - - - (25)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10)
[Sep  6 10:29:48] --- (13 headers 11 lines) ---
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2140 __sip_ack: Acked pending invite 102
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' of Request 102: Match Not Found
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:11812 handle_response_invite: SIP response 200 to RE-invite on outgoing call 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:48] Found RTP audio format 0
[Sep  6 10:29:48] Found RTP audio format 101
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:5068 process_sdp: Peer doesn't provide T.38 UDPTL
[Sep  6 10:29:48] Peer audio RTP is at port 202.137.240.82:10624
[Sep  6 10:29:48] Found description format PCMU for ID 0
[Sep  6 10:29:48] Found description format telephone-event for ID 101
[Sep  6 10:29:48] Got unsupported a:fmtp in SDP offer 
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:5301 process_sdp: T38 state changed to 0 on channel SIP/anonymous.invalid-0821af30
[Sep  6 10:29:48] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Sep  6 10:29:48] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Sep  6 10:29:48] Peer audio RTP is at port 202.137.240.82:10624
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:5381 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:5388 process_sdp: We have an owner, now see if we need to change this call
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:8140 build_route: build_route: Contact hop: <sip:anonymous@202.137.240.83:5060>
[Sep  6 10:29:48] list_route: hop: <sip:anonymous@202.137.240.83:5060>
[Sep  6 10:29:48] DEBUG[3020]: chan_sip.c:5788 reqprep: Strict routing enforced for session 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:48] set_destination: Parsing <sip:anonymous@202.137.240.83:5060> for address/port to send to
[Sep  6 10:29:48] set_destination: set destination to 202.137.240.83, port 5060
[Sep  6 10:29:48] Transmitting (no NAT) to 202.137.240.83:5060:
ACK sip:anonymous@202.137.240.83:5060 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK49a51d71
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
Contact: <sip:066504321@202.137.240.89>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
[Sep  6 10:29:48] DEBUG[3077]: rtp.c:2597 ast_rtp_raw_write: Difference is 1840, ms is 250
[Sep  6 10:29:50] DEBUG[3077]: rtp.c:875 ast_rtcp_read: Got RTCP report of 88 bytes
[Sep  6 10:29:53] 
<--- SIP read from 10.10.1.245:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B
CSeq: 102 INVITE
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
Contact: <sip:66500504@10.10.1.245>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708
Content-Type: application/sdp
Content-Length: 198

v=0
o=- 1188963420 1188963420 IN IP4 10.10.1.245
s=Polycom IP Phone
c=IN IP4 10.10.1.245
t=0 0
m=audio 10006 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000

<------------->
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK4d5f8f3f (59)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105 (65)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B (52)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: CSeq: 102 INVITE (16)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89 (56)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Contact: <sip:66500504@10.10.1.245> (35)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708 (54)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Content-Type: application/sdp (29)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Content-Length: 198 (19)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11:  (0)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: o=- 1188963420 1188963420 IN IP4 10.10.1.245 (44)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: s=Polycom IP Phone (18)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: c=IN IP4 10.10.1.245 (20)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: m=audio 10006 RTP/AVP 0 101 (27)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:53] --- (11 headers 9 lines) ---
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:2140 __sip_ack: Acked pending invite 102
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '1e81bc92200f708b3bcb19484f3adac8@202.137.240.89' of Request 102: Match Not Found
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:11814 handle_response_invite: SIP response 200 to standard invite
[Sep  6 10:29:53] Found RTP audio format 0
[Sep  6 10:29:53] Found RTP audio format 101
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5068 process_sdp: Peer doesn't provide T.38 UDPTL
[Sep  6 10:29:53] Peer audio RTP is at port 10.10.1.245:10006
[Sep  6 10:29:53] Found description format PCMU for ID 0
[Sep  6 10:29:53] Found description format telephone-event for ID 101
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5301 process_sdp: T38 state changed to 0 on channel SIP/66500504-082596b8
[Sep  6 10:29:53] Capabilities: us - 0x104 (ulaw|g729), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Sep  6 10:29:53] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Sep  6 10:29:53] Peer audio RTP is at port 10.10.1.245:10006
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5381 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5388 process_sdp: We have an owner, now see if we need to change this call
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5393 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x4 (ulaw) and not 0x100 (g729)
[Sep  6 10:29:53] DEBUG[3020]: channel.c:3020 set_format: Set channel SIP/66500504-082596b8 to read format slin
[Sep  6 10:29:53] DEBUG[3020]: channel.c:3020 set_format: Set channel SIP/66500504-082596b8 to write format slin
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call
[Sep  6 10:29:53] DEBUG[3020]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504
[Sep  6 10:29:53] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:8140 build_route: build_route: Contact hop: <sip:66500504@10.10.1.245>
[Sep  6 10:29:53] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:53] list_route: hop: <sip:66500504@10.10.1.245>
[Sep  6 10:29:53] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 3 (Busy)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5788 reqprep: Strict routing enforced for session 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
[Sep  6 10:29:53] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:53] set_destination: Parsing <sip:66500504@10.10.1.245> for address/port to send to
[Sep  6 10:29:53] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:53] set_destination: set destination to 10.10.1.245, port 5060
[Sep  6 10:29:53] Transmitting (no NAT) to 10.10.1.245:5060:
ACK sip:66500504@10.10.1.245 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK1d7e8de3
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B
Contact: <sip:anonymous@202.137.240.89>
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Remote-Party-ID: "T anonymous" <sip:anonymous@202.137.240.89>;privacy=full;screen=no
Content-Length: 0


---
[Sep  6 10:29:53] DEBUG[3105]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '3' (Busy) but we don't care because they're not a member of any queue.
[Sep  6 10:29:53] DEBUG[3077]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504-082596b8
[Sep  6 10:29:53]     -- SIP/66500504-082596b8 answered SIP/anonymous.invalid-0821af30
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:17253 sip_set_rtp_peer: Sending reinvite on SIP '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' - It's audio soon redirected to IP 10.10.1.245
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:5788 reqprep: Strict routing enforced for session 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:53] set_destination: Parsing <sip:anonymous@202.137.240.83:5060> for address/port to send to
[Sep  6 10:29:53] set_destination: set destination to 202.137.240.83, port 5060
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Sep  6 10:29:53] Audio is at 202.137.240.89 port 15408
[Sep  6 10:29:53] Adding codec 0x4 (ulaw) to SDP
[Sep  6 10:29:53] Adding non-codec 0x1 (telephone-event) to SDP
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:1634 initialize_initreq: Initializing already initialized SIP dialog 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (presumably reinvite)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:anonymous@202.137.240.83:5060 SIP/2.0 (48)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK46c2fdff (59)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 2: From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (56)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 3: To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (112)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 4: Contact: <sip:066504321@202.137.240.89> (39)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 6: CSeq: 103 INVITE (16)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 10: Supported: replaces (19)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 12: Content-Type: application/sdp (29)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 13: Content-Length: 209 (19)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4715 parse_request: Header 14:  (0)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: o=root 2989 2992 IN IP4 10.10.1.245 (35)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: s=session (9)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: c=IN IP4 10.10.1.245 (20)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: m=audio 10006 RTP/AVP 0 101 (27)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-16 (15)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10)
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10)
[Sep  6 10:29:53] Reliably Transmitting (no NAT) to 202.137.240.83:5060:
INVITE sip:anonymous@202.137.240.83:5060 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK46c2fdff
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
Contact: <sip:066504321@202.137.240.89>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 103 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 209

v=0
o=root 2989 2992 IN IP4 10.10.1.245
s=session
c=IN IP4 10.10.1.245
t=0 0
m=audio 10006 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Sep  6 10:29:53] DEBUG[3077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep  6 10:29:53] DEBUG[3077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #112
[Sep  6 10:29:53] DEBUG[3077]: rtp.c:1550 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/anonymous.invalid-0821af30' with that of 'SIP/66500504-082596b8'
[Sep  6 10:29:53] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:53] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:53] DEBUG[3077]: channel.c:2072 ast_settimeout: Scheduling timer at 0 sample intervals
[Sep  6 10:29:53] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 3 (Busy)
[Sep  6 10:29:53] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:53] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:53] DEBUG[3077]: rtp.c:2727 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Sep  6 10:29:53] DEBUG[3077]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Sep  6 10:29:53] DEBUG[3106]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '3' (Busy) but we don't care because they're not a member of any queue.
[Sep  6 10:29:53] 
<--- SIP read from 1.2.3.4:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK46c2fdff;received=202.137.240.89
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
CSeq: 103 INVITE
Server: Cantata-SIP/10.3.2.217 NAP1-6650 1
Content-Length: 0


<------------->
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 100 Trying (18)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK46c2fdff;received=202.137.240.89 (83)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (56)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (112)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: CSeq: 103 INVITE (16)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Server: Cantata-SIP/10.3.2.217 NAP1-6650 1 (42)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: Content-Length: 0 (17)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8:  (0)
[Sep  6 10:29:53] --- (8 headers 0 lines) ---
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:2191 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #112 - INVITE (got response)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' Request 103: Found
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:11812 handle_response_invite: SIP response 100 to RE-invite on outgoing call 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:53] 
<--- SIP read from 1.2.3.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK46c2fdff;received=202.137.240.89
Contact: <sip:anonymous@202.137.240.83:5060>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
CSeq: 103 INVITE
Server: Cantata-SIP/10.3.2.217 NAP1-6650 1
Allow: INVITE, BYE, REGISTER, ACK, OPTIONS, CANCEL, INFO
Supported: path
Accept: application/sdp
Content-Type: application/sdp
Content-Length: 235

v=0
o=Cantata_SDP 0 2 IN IP4 202.137.240.83
s=Cantata-SIP
c=IN IP4 202.137.240.82
t=0 0
m=audio 10624 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20

<------------->
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK46c2fdff;received=202.137.240.89 (83)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Contact: <sip:anonymous@202.137.240.83:5060> (44)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (56)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (112)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: CSeq: 103 INVITE (16)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: Server: Cantata-SIP/10.3.2.217 NAP1-6650 1 (42)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Allow: INVITE, BYE, REGISTER, ACK, OPTIONS, CANCEL, INFO (56)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Supported: path (15)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Accept: application/sdp (23)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11: Content-Type: application/sdp (29)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 235 (19)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 13:  (0)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: v=0 (3)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: o=Cantata_SDP 0 2 IN IP4 202.137.240.83 (39)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: s=Cantata-SIP (13)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: c=IN IP4 202.137.240.82 (23)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: t=0 0 (5)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: m=audio 10624 RTP/AVP 0 101 (27)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=silenceSupp:off - - - - (25)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10)
[Sep  6 10:29:53] --- (13 headers 11 lines) ---
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:2140 __sip_ack: Acked pending invite 103
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' of Request 103: Match Not Found
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:11812 handle_response_invite: SIP response 200 to RE-invite on outgoing call 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:53] Found RTP audio format 0
[Sep  6 10:29:53] Found RTP audio format 101
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5068 process_sdp: Peer doesn't provide T.38 UDPTL
[Sep  6 10:29:53] Peer audio RTP is at port 202.137.240.82:10624
[Sep  6 10:29:53] Found description format PCMU for ID 0
[Sep  6 10:29:53] Found description format telephone-event for ID 101
[Sep  6 10:29:53] Got unsupported a:fmtp in SDP offer 
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5301 process_sdp: T38 state changed to 0 on channel SIP/anonymous.invalid-0821af30
[Sep  6 10:29:53] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Sep  6 10:29:53] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Sep  6 10:29:53] Peer audio RTP is at port 202.137.240.82:10624
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5381 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5388 process_sdp: We have an owner, now see if we need to change this call
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:8079 build_route: build_route: Retaining previous route: <sip:anonymous@202.137.240.83:5060>
[Sep  6 10:29:53] DEBUG[3020]: chan_sip.c:5788 reqprep: Strict routing enforced for session 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:53] set_destination: Parsing <sip:anonymous@202.137.240.83:5060> for address/port to send to
[Sep  6 10:29:53] set_destination: set destination to 202.137.240.83, port 5060
[Sep  6 10:29:53] Transmitting (no NAT) to 202.137.240.83:5060:
ACK sip:anonymous@202.137.240.83:5060 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK1d5662d7
From: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
To: anonymous<sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
Contact: <sip:066504321@202.137.240.89>
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 103 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
[Sep  6 10:29:58] 
<--- SIP read from 202.137.240.68:5060 --->
OPTIONS sip:202.137.240.89 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.68:5060;branch=z9hG4bK767a977b;rport
From: "asterisk" <sip:asterisk@202.137.240.68>;tag=as76615985
To: <sip:202.137.240.89>
Contact: <sip:asterisk@202.137.240.68>
Call-ID: 637b0936185df5924f59ac56143e1ba5@202.137.240.68
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Wed, 05 Sep 2007 22:27:59 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


<------------->
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: OPTIONS sip:202.137.240.89 SIP/2.0 (34)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.68:5060;branch=z9hG4bK767a977b;rport (65)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" <sip:asterisk@202.137.240.68>;tag=as76615985 (61)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:202.137.240.89> (24)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: Contact: <sip:asterisk@202.137.240.68> (38)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 637b0936185df5924f59ac56143e1ba5@202.137.240.68 (56)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Date: Wed, 05 Sep 2007 22:27:59 GMT (35)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 0 (17)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 13:  (0)
[Sep  6 10:29:58] --- (13 headers 0 lines) ---
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for 637b0936185df5924f59ac56143e1ba5@202.137.240.68 - OPTIONS (No RTP)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:14944 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Sep  6 10:29:58] Looking for s in guest (domain 202.137.240.89)
[Sep  6 10:29:58] 
<--- Transmitting (no NAT) to 202.137.240.68:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 202.137.240.68:5060;branch=z9hG4bK767a977b;rport;received=202.137.240.68
From: "asterisk" <sip:asterisk@202.137.240.68>;tag=as76615985
To: <sip:202.137.240.89>;tag=as62a4ef8b
Call-ID: 637b0936185df5924f59ac56143e1ba5@202.137.240.68
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Accept: application/sdp
Content-Length: 0


<------------>
[Sep  6 10:29:58] Scheduling destruction of SIP dialog '637b0936185df5924f59ac56143e1ba5@202.137.240.68' in 32000 ms (Method: OPTIONS)
[Sep  6 10:29:58] DEBUG[3020]: chan_sip.c:15162 sipsock_read: SIP message could not be handled, bad request: 637b0936185df5924f59ac56143e1ba5@202.137.240.68                       
[Sep  6 10:29:59] 
<--- SIP read from 1.2.3.4:5060 --->
BYE sip:066504321@202.137.240.89 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-2fc2-1189031809-11403-181
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 2 BYE
Max-Forwards: 70
To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
From: <sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
User-Agent: Cantata-SIP/10.3.2.217 NAP1-6650 1
Reason: Q.850 ;cause=16 ;text="Normal call clearing"
Content-Length: 0


<------------->
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: BYE sip:066504321@202.137.240.89 SIP/2.0 (40)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-2fc2-1189031809-11403-181 (83)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83 (57)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: CSeq: 2 BYE (11)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: Max-Forwards: 70 (16)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18 (54)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: From: <sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325 (105)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Cantata-SIP/10.3.2.217 NAP1-6650 1 (46)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Reason: Q.850 ;cause=16 ;text="Normal call clearing" (52)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 10:  (0)
[Sep  6 10:29:59] --- (10 headers 0 lines) ---
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:14944 handle_request: **** Received BYE (8) - Command in SIP BYE
[Sep  6 10:29:59] Sending to 1.2.3.4 : 5060 (NAT)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:1646 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:14486 handle_request_bye: Received bye, issuing owner hangup
[Sep  6 10:29:59] 
<--- Transmitting (NAT) to 1.2.3.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 202.137.240.83:5060;rport;branch=z9hG4bK-2fc2-1189031809-11403-181;received=1.2.3.4
From: <sip:anonymous@anonymous.invalid;otg=ChanGroup_NAP_SPOLI2>;tag=95ffcd055e0f78f7d5d397020e89288d0325
To: <sip:066504321@202.137.240.89:5060>;tag=as0d9f7c18
Call-ID: 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83
CSeq: 2 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:066504321@202.137.240.89>
Content-Length: 0


<------------>
[Sep  6 10:29:59] DEBUG[3077]: channel.c:4014 ast_generic_bridge: Didn't get a frame from channel: SIP/anonymous.invalid-0821af30
[Sep  6 10:29:59] DEBUG[3077]: channel.c:4338 ast_channel_bridge: Bridge stops bridging channels SIP/anonymous.invalid-0821af30 and SIP/66500504-082596b8
[Sep  6 10:29:59] DEBUG[3077]: channel.c:1764 ast_hangup: Hanging up channel 'SIP/66500504-082596b8'
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:3445 sip_hangup: Hangup call SIP/66500504-082596b8, SIP callid 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89)
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:3454 sip_hangup: update_call_counter(66500504) - decrement call limit counter on hangup
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:3184 update_call_counter: Call to peer '66500504' removed from call limit 1
[Sep  6 10:29:59] DEBUG[3077]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504
[Sep  6 10:29:59] Scheduling destruction of SIP dialog '1e81bc92200f708b3bcb19484f3adac8@202.137.240.89' in 6400 ms (Method: INVITE)
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:5788 reqprep: Strict routing enforced for session 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
[Sep  6 10:29:59] set_destination: Parsing <sip:66500504@10.10.1.245> for address/port to send to
[Sep  6 10:29:59] set_destination: set destination to 10.10.1.245, port 5060
[Sep  6 10:29:59] Reliably Transmitting (no NAT) to 10.10.1.245:5060:
BYE sip:66500504@10.10.1.245 SIP/2.0
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK38e3953e
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
CSeq: 103 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
Remote-Party-ID: "T anonymous" <sip:anonymous@202.137.240.89>;privacy=full;screen=no
Content-Length: 0


---
[Sep  6 10:29:59] DEBUG[3077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #116
[Sep  6 10:29:59] DEBUG[3077]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/66500504-082596b8
[Sep  6 10:29:59] DEBUG[3077]: rtp.c:1499 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Sep  6 10:29:59] DEBUG[3077]: app_dial.c:1686 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Sep  6 10:29:59] DEBUG[3077]: pbx.c:2407 __ast_pbx_run: Spawn extension (airnetmainivr,3,9) exited non-zero on 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:59]   == Spawn extension (airnetmainivr, 3, 9) exited non-zero on 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:59] DEBUG[3077]: channel.c:1547 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:59] DEBUG[3077]: pbx.c:1809 pbx_extension_helper: Launching 'Hangup'
[Sep  6 10:29:59]     -- Executing [h@airnetmainivr:1] Hangup("SIP/anonymous.invalid-0821af30", "") in new stack
[Sep  6 10:29:59] DEBUG[3077]: pbx.c:2530 __ast_pbx_run: Spawn extension (airnetmainivr,h,1) exited non-zero on 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:59]   == Spawn extension (airnetmainivr, h, 1) exited non-zero on 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:59] DEBUG[3077]: channel.c:1764 ast_hangup: Hanging up channel 'SIP/anonymous.invalid-0821af30'
[Sep  6 10:29:59] DEBUG[3077]: chan_sip.c:3445 sip_hangup: Hangup call SIP/anonymous.invalid-0821af30, SIP callid 7eac-49c-852007223629-NAP1-6650-1@202.137.240.83)
[Sep  6 10:29:59] DEBUG[3077]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/anonymous.invalid-0821af30
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:59] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 1 (Not in use)
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:59] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:59] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/66500504 - state 1 (Not in use)
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 66500504
[Sep  6 10:29:59] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer 66500504
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - anonymous.invalid
[Sep  6 10:29:59] DEBUG[2993]: chan_sip.c:15574 sip_devicestate: Checking device state for peer anonymous.invalid
[Sep  6 10:29:59] DEBUG[3077]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record.
[Sep  6 10:29:59] DEBUG[3107]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  6 10:29:59] DEBUG[3108]: app_queue.c:548 changethread: Device 'SIP/66500504' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Sep  6 10:29:59] DEBUG[3077]: cdr_addon_mysql.c:226 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2007-09-06 10:29:40','\"T anonymous\" <anonymous>','anonymous','3','airnetmainivr', 'SIP/anonymous.invalid-0821af30','SIP/66500504-082596b8','Dial','SIP/66500503&SIP/66500504&SIP/66500506&SIP/66500512&SIP/66500562&SIP/66500553|1',19,16,'ANSWERED',3,'','VPBXIVRMenu:3-Support>')
[Sep  6 10:29:59] DEBUG[2993]: devicestate.c:287 do_state_change: Changing state for SIP/anonymous.invalid - state 4 (Invalid)
[Sep  6 10:29:59] DEBUG[3109]: app_queue.c:548 changethread: Device 'SIP/anonymous.invalid' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Sep  6 10:29:59] 
<--- SIP read from 10.10.1.245:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK38e3953e
From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105
To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B
CSeq: 103 BYE
Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89
Contact: <sip:66500504@10.10.1.245>
User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708
Content-Length: 0


<------------->
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 202.137.240.89:5060;branch=z9hG4bK38e3953e (59)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 2: From: "T anonymous" <sip:anonymous@202.137.240.89>;tag=as79a5f105 (65)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 3: To: <sip:66500504@10.10.1.245>;tag=88A2B982-5D0E104B (52)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 4: CSeq: 103 BYE (13)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1e81bc92200f708b3bcb19484f3adac8@202.137.240.89 (56)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 6: Contact: <sip:66500504@10.10.1.245> (35)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_500-UA/2.1.0.2708 (54)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 8: Content-Length: 0 (17)
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:4715 parse_request: Header 9:  (0)
[Sep  6 10:29:59] --- (9 headers 0 lines) ---
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #116
[Sep  6 10:29:59] DEBUG[3020]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '1e81bc92200f708b3bcb19484f3adac8@202.137.240.89' of Request 103: Match Not Found
[Sep  6 10:29:59] Really destroying SIP dialog '1e81bc92200f708b3bcb19484f3adac8@202.137.240.89' Method: INVITE
[Sep  6 10:29:59] Really destroying SIP dialog '7eac-49c-852007223629-NAP1-6650-1@202.137.240.83' Method: BYE