<--- SIP read from 192.168.30.190:5060 --->
INVITE sip:6003@192.168.30.254:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bK54dc72f86769C277
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>
CSeq: 1 INVITE
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Supported: 100rel,replaces
Allow-Events: talk,hold,conference
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 298

v=0
o=- 1262873226 1262873226 IN IP4 192.168.30.190
s=Polycom IP Phone
c=IN IP4 192.168.30.190
t=0 0
a=sendrecv
m=audio 2234 RTP/AVP 9 0 8 18 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000

<------------->
--- (15 headers 13 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2899 do_setnat: Setting NAT on VRTP to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2904 do_setnat: Setting NAT on UDPTL to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for 93c63026-5e56f305-5c3cf214@192.168.30.190 - INVITE (With RTP)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:1766 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces"
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:1774 parse_sip_options: Found SIP option: -100rel-
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:1780 parse_sip_options: Matched SIP option: 100rel
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:1774 parse_sip_options: Found SIP option: -replaces-
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:1780 parse_sip_options: Matched SIP option: replaces
Sending to 192.168.30.190 : 5060 (no NAT)
Using INVITE request as basis request - 93c63026-5e56f305-5c3cf214@192.168.30.190
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2899 do_setnat: Setting NAT on VRTP to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2904 do_setnat: Setting NAT on UDPTL to Off
lab*CLI>
<--- Reliably Transmitting (no NAT) to 192.168.30.190:5060 --->
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bK54dc72f86769C277;received=192.168.30.190
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>;tag=as2c9b1da8
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
CSeq: 1 INVITE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
upported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4a341ee8"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '93c63026-5e56f305-5c3cf214@192.168.30.190' in 32000 ms (Method: INVITE)
Found user '6002'
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
ACK sip:6003@192.168.30.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bK54dc72f86769C277
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>;tag=as2c9b1da8
CSeq: 1 ACK
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Max-Forwards: 70
Content-Length: 0


<------------->
--- (12 headers 0 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '93c63026-5e56f305-5c3cf214@192.168.30.190' of Response 1: Match Found
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
INVITE sip:6003@192.168.30.254:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bKafe1ae61B4EC6430
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>
CSeq: 2 INVITE
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Supported: 100rel,replaces
Allow-Events: talk,hold,conference
Proxy-Authorization: Digest username="6002", realm="asterisk", nonce="4a341ee8", uri="sip:6003@192.168.30.254:5060;user=phone", response="d46df0381a36ebd0f1f4dd52c0fa6fce", algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 298

v=0
o=- 1262873226 1262873226 IN IP4 192.168.30.190
s=Polycom IP Phone
c=IN IP4 192.168.30.190
t=0 0
a=sendrecv
m=audio 2234 RTP/AVP 9 0 8 18 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000

<------------->
--- (16 headers 13 lines) ---
Sending to 192.168.30.190 : 5060 (no NAT)
Using INVITE request as basis request - 93c63026-5e56f305-5c3cf214@192.168.30.190
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2899 do_setnat: Setting NAT on VRTP to Off
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2904 do_setnat: Setting NAT on UDPTL to Off
Found user '6002'
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP o=- 1262873226 1262873226 IN IP4 192.168.30.190... UNSUPPORTED.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP c=IN IP4 192.168.30.190... OK.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP a=sendrecv... OK.
Found RTP audio format 9
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 18
Found RTP audio format 101
Found audio description format G722 for ID 9
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
Found audio description format PCMU for ID 0
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
Found audio description format PCMA for ID 8
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
Found audio description format G729 for ID 18
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
Found audio description format telephone-event for ID 101
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5596 process_sdp: T38 state changed to 0 on channel <none>
Capabilities: us - 0x1004 (ulaw|g722), peer - audio=0x110c (ulaw|alaw|g729|g722)/video=0x0 (nothing), combined - 0x1004 (ulaw|g722)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5624 process_sdp: Our T38 capability = (3856), peer T38 capability (0), joint T38 capability (3856)
Peer audio RTP is at port 192.168.30.190:2234
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5721 process_sdp: Peer doesn't provide T.38 UDPTL
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:5729 process_sdp: We're settling with these formats: 0x1004 (ulaw|g722)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:15133 handle_request_invite: Checking SIP call limits for device 6002
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:3393 update_call_counter: Updating call counter for incoming call
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:3470 update_call_counter: Call from peer '6002' is 1 out of 8
[Jan  7 09:07:12] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002
Looking for 6003 in default-super (domain 192.168.30.254)
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:12] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 2 (In use)
[Jan  7 09:07:12] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6002' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session b94398ca-9c3d9863-872b7064@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4c03e6a6;rport
From: <sip:6002@192.168.30.254>;tag=as3ac6d3c7
To: "John Doe" <sip:6010@192.168.30.254>;tag=E555850D-9395049E
Contact: <sip:6002@192.168.30.254>
Call-ID: b94398ca-9c3d9863-872b7064@192.168.30.194
CSeq: 111 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6002">
<address uri="sip:6002@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6002[default-local] new state InUse for Notify User 6010
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 439ba601-121a2dd0-186b64cf@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK1693307e;rport
From: <sip:6002@192.168.30.254>;tag=as25231e62
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=49E351FE-54EAAC5D
Contact: <sip:6002@192.168.30.254>
Call-ID: 439ba601-121a2dd0-186b64cf@192.168.30.190
CSeq: 139 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6002">
<address uri="sip:6002@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6002[default-local] new state InUse for Notify User 6002
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:4244 sip_new: *** Our native formats are 0x4 (ulaw)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:4245 sip_new: *** Joint capabilities are 0x1004 (ulaw|g722)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:4246 sip_new: *** Our capabilities are 0x1004 (ulaw|g722)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:4247 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:4270 sip_new: This channel will not be able to handle video.
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:8920 build_route: build_route: Contact hop: <sip:6002@192.168.30.190:5060>
list_route: hop: <sip:6002@192.168.30.190:5060>
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:15232 handle_request_invite: SIP/6002-00000029: New call is still down.... Trying...

<--- Transmitting (no NAT) to 192.168.30.190:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bKafe1ae61B4EC6430;received=192.168.30.190
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
CSeq: 2 INVITE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:6003@192.168.30.254>
Content-Length: 0


<------------>
[Jan  7 09:07:12] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:12] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 2 (In use)
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:12] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6002' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6003@default-super:1] Set("SIP/6002-00000029", "__PICKUPMARK=6003") in new stack
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4c03e6a6;rport
From: <sip:6002@192.168.30.254>;tag=as3ac6d3c7
To: "John Doe" <sip:6010@192.168.30.254>;tag=E555850D-9395049E
CSeq: 111 NOTIFY
Call-ID: b94398ca-9c3d9863-872b7064@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 111
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'b94398ca-9c3d9863-872b7064@192.168.30.194' of Request 111: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:12] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '4'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [6003@default-super:2] GotoIf("SIP/6002-00000029", "0?4") in new stack
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:6100 pbx_builtin_gotoif: Not taking any branch
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6002'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6003@default-super:3] Set("SIP/6002-00000029", "GROUP(OUTGOING)=6002") in new stack
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6003@default-super:4] Set("SIP/6002-00000029", "OUTBOUND_GROUP_ONCE=6003@INCOMING") in new stack
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6003@default-super:5] Set("SIP/6002-00000029", "GROUPCOUNT=0") in new stack
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6003@default-super:6] Set("SIP/6002-00000029", "GROUPCOUNT2=0") in new stack
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK1693307e;rport
From: <sip:6002@192.168.30.254>;tag=as25231e62
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=49E351FE-54EAAC5D
CSeq: 139 NOTIFY
Call-ID: 439ba601-121a2dd0-186b64cf@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 139
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '439ba601-121a2dd0-186b64cf@192.168.30.190' of Request 139: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6003@default-super:7] Set("SIP/6002-00000029", "SCOPSERV_DBPUT(default/wrapup/6003/lastcall)=1262873232.82") in new stack
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1262873232.82'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'default/wrapup/6003/lastcall'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Macro'
    -- Executing [6003@default-super:8] Macro("SIP/6002-00000029", "default-dial|SIP/6003|6003|default|20|en|b6003@default|tkK||default||Local/0@default-local/n|disa") in new stack
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6002'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'Reception 6002'
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-default-dial:1] NoOp("SIP/6002-00000029", ""CALL TO LOCAL EXTENSION FROM 6002(Reception 6002)"") in new stack
[Jan  7 09:07:12] DEBUG[16612]: app_macro.c:379 _macro_exec: Executed application: NoOp
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-default-dial:2] Set("SIP/6002-00000029", "__PICKUPMARK=6003") in new stack
[Jan  7 09:07:12] DEBUG[16612]: app_macro.c:379 _macro_exec: Executed application: Set
[Jan  7 09:07:12] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'AGI'
    -- Executing [s@macro-default-dial:3] AGI("SIP/6002-00000029", "agi://127.0.0.1:4573/dial") in new stack
AGI Tx >> agi_network: yes
AGI Tx >> agi_network_script: dial
AGI Tx >> agi_request: agi://127.0.0.1:4573/dial
AGI Tx >> agi_channel: SIP/6002-00000029
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1262873232.82
AGI Tx >> agi_callerid: 6002
AGI Tx >> agi_calleridname: Reception 6002
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 6003
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-default-dial
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode: 6002
AGI Tx >>
[Jan  7 09:07:12] DEBUG[16614]: manager.c:2233 process_message: Manager received command 'login'
  == Parsing '/etc/asterisk/manager.conf': [Jan  7 09:07:12] DEBUG[16614]: config.c:895 config_text_file_load: Parsing /etc/asterisk/manager.conf
Found
[Jan  7 09:07:12] DEBUG[16614]: acl.c:355 ast_append_ha: 127.0.0.1/255.255.255.255 appended to acl for peer
[Jan  7 09:07:12] DEBUG[16614]: acl.c:370 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.1
AGI Rx << GET VARIABLE ARG1
AGI Tx >> 200 result=1 (SIP/6003)
AGI Rx << GET VARIABLE ARG2
AGI Tx >> 200 result=1 (6003)
AGI Rx << GET VARIABLE ARG3
AGI Tx >> 200 result=1 (default)
AGI Rx << GET VARIABLE ARG4
AGI Tx >> 200 result=1 (20)
AGI Rx << GET VARIABLE ARG5
AGI Tx >> 200 result=1 (en)
AGI Rx << GET VARIABLE ARG6
AGI Tx >> 200 result=1 (b6003@default)
AGI Rx << GET VARIABLE ARG7
AGI Tx >> 200 result=1 (tkK)
AGI Rx << GET VARIABLE ARG8
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE ARG9
AGI Tx >> 200 result=1 (default)
AGI Rx << GET VARIABLE ARG10
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE ARG11
AGI Tx >> 200 result=1 (Local/0@default-local/n)
AGI Rx << GET VARIABLE ARG12
AGI Tx >> 200 result=1 (disa)
AGI Rx << GET VARIABLE EXT_ACCODE
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE MACRO_PRIORITY
AGI Tx >> 200 result=1 (8)
AGI Rx << GET VARIABLE CALLBACK_ON_HANGUP
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE EPICCALLID
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE INCOMINGLINE
AGI Tx >> 200 result=0
AGI Rx << SET VARIABLE CHANNEL(language) "en"
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE CHANNEL(musicclass) "default"
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE AUTO_RECORDING
AGI Tx >> 200 result=1 (6002)
AGI Rx << SET VARIABLE TOUCH_MONITOR "6002_1262873232.82"
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE TOUCH_MIXMONITOR "6002_1262873232.82"
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE FORCE_RECORDING
AGI Tx >> 200 result=0
AGI Rx << EXEC MixMonitor 1262873232.82.WAV|b
    -- AGI Script Executing Application: (MixMonitor) Options: (1262873232.82.WAV|b)
AGI Tx >> 200 result=0
  == Begin MixMonitor Recording SIP/6002-00000029
AGI Rx << SET VARIABLE AUDIOHOOK_INHERIT(MixMonitor) "yes"
[Jan  7 09:07:12] DEBUG[16612]: func_audiohookinherit.c:146 setup_inheritable_audiohook: Set audiohook MixMonitor to be inheritable
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE LIMIT_IN_DEFAULT_6003
AGI Tx >> 200 result=1 (4)
AGI Rx << GET VARIABLE GROUPCOUNT
AGI Tx >> 200 result=1 (0)
AGI Rx << GET VARIABLE GROUPCOUNT2
AGI Tx >> 200 result=1 (0)
[Jan  7 09:07:12] DEBUG[16614]: manager.c:2233 process_message: Manager received command 'ExtensionState'
[Jan  7 09:07:12] DEBUG[16614]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
AGI Rx << EXEC NoOp STATUS: 0
    -- AGI Script Executing Application: (NoOp) Options: (STATUS:)
AGI Tx >> 200 result=0
AGI Rx << SET CALLERID "Reception 6002"<6002>
AGI Tx >> 200 result=1
AGI Rx << EXEC Dial SIP/6003|20|tkKT|
    -- AGI Script Executing Application: (Dial) Options: (SIP/6003|20|tkKT|)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:17371 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to Off
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4244 sip_new: *** Our native formats are 0x4 (ulaw)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4245 sip_new: *** Joint capabilities are 0x0 (nothing)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4246 sip_new: *** Our capabilities are 0x1004 (ulaw|g722)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4247 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan  7 09:07:12] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4249 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:4270 sip_new: This channel will not be able to handle video.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable TOUCH_MIXMONITOR.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable TOUCH_MONITOR.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3771 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG12.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG11.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG10.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG9.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG8.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG7.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG6.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG5.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG4.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG3.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG2.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable GROUPCOUNT2.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable GROUPCOUNT.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable INBOUND_GROUP.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable AUTO_RECORDING.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable EXTCONTEXT.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jan  7 09:07:12] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:3185 sip_call: Outgoing Call for 6003
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:3393 update_call_counter: Updating call counter for outgoing call
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:3470 update_call_counter: Call to peer '6003' is 1 out of 4
[Jan  7 09:07:12] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6003
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:12] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6003 - state 6 (Ringing)
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session b9119199-1a151d0a-bc1ce6a3@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK5f52e0c6;rport
From: <sip:6003@192.168.30.254>;tag=as0a78822f
To: "John Doe" <sip:6010@192.168.30.254>;tag=30FD18A4-1FBC974D
Contact: <sip:6003@192.168.30.254>
Call-ID: b9119199-1a151d0a-bc1ce6a3@192.168.30.194
CSeq: 115 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6003">
<address uri="sip:6003@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6003[default-local] new state Ringing for Notify User 6010
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:12] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 7eb1fb08-f5556787-ddf48236@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK6008c81f;rport
From: <sip:6003@192.168.30.254>;tag=as2b2192a7
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=F9398215-2D9A4E24
Contact: <sip:6003@192.168.30.254>
Call-ID: 7eb1fb08-f5556787-ddf48236@192.168.30.190
CSeq: 149 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6003">
<address uri="sip:6003@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6003[default-local] new state Ringing for Notify User 6002
[Jan  7 09:07:12] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6003' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:3200 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:6957 add_sdp: ** Our capability: 0x1004 (ulaw|g722) Video flag: False
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:6958 add_sdp: ** Our prefcodec: 0x4 (ulaw)
Audio is at 192.168.30.254 port 18412
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x1000 (g722) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:7075 add_sdp: -- Done with adding codecs to SDP
[Jan  7 09:07:12] DEBUG[16612]: chan_sip.c:7184 add_sdp: Done building SDP. Settling with this capability: 0x1004 (ulaw|g722)
Reliably Transmitting (no NAT) to 192.168.30.85:5060:
INVITE sip:6003@192.168.30.85:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK11d3c699;rport
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
To: <sip:6003@192.168.30.85:5060>
Contact: <sip:6002@192.168.30.254>
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
CSeq: 102 INVITE
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Remote-Party-ID: "Reception 6002" <sip:6002@192.168.30.254>;privacy=off;screen=no
Date: Thu, 07 Jan 2010 14:07:12 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Type: application/sdp
Content-Length: 268

v=0
o=root 10449 10449 IN IP4 192.168.30.254
s=session
c=IN IP4 192.168.30.254
t=0 0
m=audio 18412 RTP/AVP 0 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
    -- Called 6003
[Jan  7 09:07:12] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:12] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:12] DEBUG[10456]: channel.c:1133 channel_find_locked: Avoiding initial deadlock for channel '0x96560c0'
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK6008c81f;rport
From: <sip:6003@192.168.30.254>;tag=as2b2192a7
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=F9398215-2D9A4E24
CSeq: 149 NOTIFY
Call-ID: 7eb1fb08-f5556787-ddf48236@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 149
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '7eb1fb08-f5556787-ddf48236@192.168.30.190' of Request 149: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived

<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK5f52e0c6;rport
From: <sip:6003@192.168.30.254>;tag=as0a78822f
To: "John Doe" <sip:6010@192.168.30.254>;tag=30FD18A4-1FBC974D
CSeq: 115 NOTIFY
Call-ID: b9119199-1a151d0a-bc1ce6a3@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 115
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'b9119199-1a151d0a-bc1ce6a3@192.168.30.194' of Request 115: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
lab*CLI>
<--- SIP read from 192.168.30.85:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK11d3c699;rport
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
To: <sip:6003@192.168.30.85:5060>;tag=319B8481-11CA4822
CSeq: 102 INVITE
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
Contact: <sip:6003@192.168.30.85:5060>
User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (10 headers 0 lines) ---
[Jan  7 09:07:12] DEBUG[10471]: chan_sip.c:2313 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254' Request 102: Found
[Jan  7 09:07:12] DEBUG[13677]: manager.c:2233 process_message: Manager received command 'Ping'
lab*CLI>
<--- SIP read from 192.168.30.85:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK11d3c699;rport
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
To: <sip:6003@192.168.30.85:5060>;tag=319B8481-11CA4822
CSeq: 102 INVITE
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
Contact: <sip:6003@192.168.30.85:5060>
User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439
Allow-Events: talk,hold,conference
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:13] DEBUG[10471]: chan_sip.c:2313 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254' Request 102: Found
[Jan  7 09:07:13] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6003
[Jan  7 09:07:13] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
    -- SIP/6003-0000002a is ringing
[Jan  7 09:07:13] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6003 - state 6 (Ringing)
lab*CLI>
<--- Transmitting (no NAT) to 192.168.30.190:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bKafe1ae61B4EC6430;received=192.168.30.190
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>;tag=as57fed4ba
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
CSeq: 2 INVITE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:6003@192.168.30.254>
Content-Length: 0


<------------>
[Jan  7 09:07:13] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6003' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  7 09:07:13] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:13] DEBUG[10471]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Reliably Transmitting (no NAT) to 192.168.30.115:5060:
OPTIONS sip:6006@192.168.30.115:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4583448e;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as52ce1a12
To: <sip:6006@192.168.30.115:5060;transport=udp>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4df20db7381d07424046bfdd0ea7c889@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:13] DEBUG[10471]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Reliably Transmitting (no NAT) to 192.168.30.188:5060:
OPTIONS sip:6005@192.168.30.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK63adfd28;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as4ff1ea85
To: <sip:6005@192.168.30.188:5060>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 2feb981131b59c954034e0544a4b3a23@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:13] DEBUG[4456]: manager.c:2233 process_message: Manager received command 'Command'
[Jan  7 09:07:13] DEBUG[13051]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:13] DEBUG[13056]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:13] DEBUG[10471]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Reliably Transmitting (no NAT) to 192.168.30.162:5060:
OPTIONS sip:6000@192.168.30.162:5060;line=95k0vvpm SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK582c46cd;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as5803c8ac
To: <sip:6000@192.168.30.162:5060;line=95k0vvpm>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4b471e254fae203f04f397954e234e60@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:13] DEBUG[13036]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:14] DEBUG[13057]: manager.c:2233 process_message: Manager received command 'Ping'
Retransmitting #1 (no NAT) to 192.168.30.115:5060:
OPTIONS sip:6006@192.168.30.115:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4583448e;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as52ce1a12
To: <sip:6006@192.168.30.115:5060;transport=udp>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4df20db7381d07424046bfdd0ea7c889@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
lab*CLI>
<--- SIP read from 192.168.30.85:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK11d3c699;rport
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
To: <sip:6003@192.168.30.85:5060>;tag=319B8481-11CA4822
CSeq: 102 INVITE
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
Contact: <sip:6003@192.168.30.85:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Type: application/sdp
Content-Length: 201

v=0
o=- 1262873230 1262873230 IN IP4 192.168.30.85
s=Polycom IP Phone
c=IN IP4 192.168.30.85
t=0 0
m=audio 2232 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000

<------------->
--- (12 headers 9 lines) ---
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 102
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254' of Request 102: Match Found
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP o=- 1262873230 1262873230 IN IP4 192.168.30.85... UNSUPPORTED.
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED.
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP c=IN IP4 192.168.30.85... OK.
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
Found RTP audio format 0
Found RTP audio format 101
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
Found audio description format PCMU for ID 0
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
Found audio description format telephone-event for ID 101
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5596 process_sdp: T38 state changed to 0 on channel SIP/6003-0000002a
Capabilities: us - 0x1004 (ulaw|g722), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5624 process_sdp: Our T38 capability = (3856), peer T38 capability (0), joint T38 capability (3856)
Peer audio RTP is at port 192.168.30.85:2232
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:5729 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:3393 update_call_counter: Updating call counter for outgoing call
[Jan  7 09:07:14] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6003
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:14] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6003 - state 2 (In use)
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:14] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6003' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session b9119199-1a151d0a-bc1ce6a3@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK0a8cf47d;rport
From: <sip:6003@192.168.30.254>;tag=as0a78822f
To: "John Doe" <sip:6010@192.168.30.254>;tag=30FD18A4-1FBC974D
Contact: <sip:6003@192.168.30.254>
Call-ID: b9119199-1a151d0a-bc1ce6a3@192.168.30.194
CSeq: 116 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6003">
<address uri="sip:6003@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6003[default-local] new state InUse for Notify User 6010
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 7eb1fb08-f5556787-ddf48236@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK29185777;rport
From: <sip:6003@192.168.30.254>;tag=as2b2192a7
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=F9398215-2D9A4E24
Contact: <sip:6003@192.168.30.254>
Call-ID: 7eb1fb08-f5556787-ddf48236@192.168.30.190
CSeq: 150 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6003">
<address uri="sip:6003@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6003[default-local] new state InUse for Notify User 6002
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:8920 build_route: build_route: Contact hop: <sip:6003@192.168.30.85:5060>
list_route: hop: <sip:6003@192.168.30.85:5060>
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:6466 reqprep: Strict routing enforced for session 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
set_destination: Parsing <sip:6003@192.168.30.85:5060> for address/port to send to
set_destination: set destination to 192.168.30.85, port 5060
Transmitting (no NAT) to 192.168.30.85:5060:
ACK sip:6003@192.168.30.85:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK0aee49a3;rport
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
To: <sip:6003@192.168.30.85:5060>;tag=319B8481-11CA4822
Contact: <sip:6002@192.168.30.254>
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
CSeq: 102 ACK
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Remote-Party-ID: "Reception 6002" <sip:6002@192.168.30.254>;privacy=off;screen=no
Content-Length: 0


---
Retransmitting #1 (no NAT) to 192.168.30.188:5060:
OPTIONS sip:6005@192.168.30.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK63adfd28;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as4ff1ea85
To: <sip:6005@192.168.30.188:5060>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 2feb981131b59c954034e0544a4b3a23@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:14] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6003
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:14] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6003 - state 2 (In use)
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:14] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6003' changed to state '2' (In use) but we don't care because they're not a member of any queue.
    -- SIP/6003-0000002a answered SIP/6002-00000029
[Jan  7 09:07:14] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002
[Jan  7 09:07:14] DEBUG[16612]: chan_sip.c:3873 sip_answer: SIP answering channel: SIP/6002-00000029
[Jan  7 09:07:14] DEBUG[16612]: chan_sip.c:7242 transmit_response_with_sdp: Setting framing from config on incoming call
[Jan  7 09:07:14] DEBUG[16612]: chan_sip.c:6957 add_sdp: ** Our capability: 0x1004 (ulaw|g722) Video flag: True
[Jan  7 09:07:14] DEBUG[16612]: chan_sip.c:6958 add_sdp: ** Our prefcodec: 0x0 (nothing)
Audio is at 192.168.30.254 port 14980
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x1000 (g722) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Jan  7 09:07:14] DEBUG[16612]: chan_sip.c:7075 add_sdp: -- Done with adding codecs to SDP
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:14] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 2 (In use)
[Jan  7 09:07:14] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:14] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6002' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:14] DEBUG[16612]: chan_sip.c:7184 add_sdp: Done building SDP. Settling with this capability: 0x1004 (ulaw|g722)

<--- Reliably Transmitting (no NAT) to 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bKafe1ae61B4EC6430;received=192.168.30.190
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>;tag=as57fed4ba
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
CSeq: 2 INVITE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:6003@192.168.30.254>
Content-Type: application/sdp
Content-Length: 268

v=0
o=root 10449 10449 IN IP4 192.168.30.254
s=session
c=IN IP4 192.168.30.254
t=0 0
m=audio 14980 RTP/AVP 0 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>

<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK0a8cf47d;rport
From: <sip:6003@192.168.30.254>;tag=as0a78822f
To: "John Doe" <sip:6010@192.168.30.254>;tag=30FD18A4-1FBC974D
CSeq: 116 NOTIFY
Call-ID: b9119199-1a151d0a-bc1ce6a3@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 116
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'b9119199-1a151d0a-bc1ce6a3@192.168.30.194' of Request 116: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:14] DEBUG[13043]: manager.c:2233 process_message: Manager received command 'Ping'

<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK29185777;rport
From: <sip:6003@192.168.30.254>;tag=as2b2192a7
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=F9398215-2D9A4E24
CSeq: 150 NOTIFY
Call-ID: 7eb1fb08-f5556787-ddf48236@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 150
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '7eb1fb08-f5556787-ddf48236@192.168.30.190' of Request 150: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
ACK sip:6003@192.168.30.254 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.190:5060;branch=z9hG4bK360dacbdDB6E894C
From: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
To: <sip:6003@192.168.30.254;user=phone>;tag=as57fed4ba
CSeq: 2 ACK
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Max-Forwards: 70
Content-Length: 0


<------------->
--- (12 headers 0 lines) ---
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '93c63026-5e56f305-5c3cf214@192.168.30.190' of Response 2: Match Found
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:259 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9632578
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:2898 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:2915 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:259 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9632578
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:2898 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:2915 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[13055]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:14] DEBUG[13047]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #1 (no NAT) to 192.168.30.162:5060:
OPTIONS sip:6000@192.168.30.162:5060;line=95k0vvpm SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK582c46cd;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as5803c8ac
To: <sip:6000@192.168.30.162:5060;line=95k0vvpm>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4b471e254fae203f04f397954e234e60@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[13042]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4)
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 42 (*), at 192.168.30.85
[Jan  7 09:07:14] DEBUG[16612]: channel.c:4362 ast_generic_bridge: Got DTMF begin on channel (SIP/6003-0000002a)
[Jan  7 09:07:14] DEBUG[16612]: channel.c:4679 ast_channel_bridge: Bridge stops bridging channels SIP/6002-00000029 and SIP/6003-0000002a
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4)
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4)
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SUBSCRIBE sip:99057126386@192.168.30.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.194:5060;branch=z9hG4bK44b2ea4023F38749
From: "John Doe" <sip:6010@192.168.30.254>;tag=12A542FD-68D9A80E
To: <sip:99057126386@192.168.30.254>
CSeq: 1 SUBSCRIBE
Call-ID: 16618e3a-f086df53-ab8784d4@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Accept: application/xpidf+xml,text/xml+msrtc.pidf
Max-Forwards: 70
Expires: 3600
Content-Length: 0


<------------->
--- (15 headers 0 lines) ---
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for 16618e3a-f086df53-ab8784d4@192.168.30.194 - SUBSCRIBE (No RTP)
Creating new subscription
Sending to 192.168.30.194 : 5060 (no NAT)
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:8920 build_route: build_route: Contact hop: <sip:6010@192.168.30.194:5060>
list_route: hop: <sip:6010@192.168.30.194:5060>
Found peer '6010'

<--- Transmitting (no NAT) to 192.168.30.194:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.30.194:5060;branch=z9hG4bK44b2ea4023F38749;received=192.168.30.194
From: "John Doe" <sip:6010@192.168.30.254>;tag=12A542FD-68D9A80E
To: <sip:99057126386@192.168.30.254>;tag=as6d20257d
Call-ID: 16618e3a-f086df53-ab8784d4@192.168.30.194
CSeq: 1 SUBSCRIBE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="650e592e"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '16618e3a-f086df53-ab8784d4@192.168.30.194' in 6400 ms (Method: SUBSCRIBE)
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4)
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 42 (*), at 192.168.30.85
[Jan  7 09:07:14] DEBUG[16612]: channel.c:4362 ast_generic_bridge: Got DTMF end on channel (SIP/6003-0000002a)
[Jan  7 09:07:14] DEBUG[16612]: channel.c:4679 ast_channel_bridge: Bridge stops bridging channels SIP/6002-00000029 and SIP/6003-0000002a
[Jan  7 09:07:14] DEBUG[16612]: res_features.c:1482 feature_interpret: Feature interpret: chan=SIP/6002-00000029, peer=SIP/6003-0000002a, code=*, sense=2, features=34, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-1000#tagcode-1001#tagcode-1002#tagcode-1003
[Jan  7 09:07:14] DEBUG[16612]: res_features.c:2126 ast_bridge_call: Set time limit to 1000
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SUBSCRIBE sip:99057126386@192.168.30.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.194:5060;branch=z9hG4bKbb4a9c4725FD71E8
From: "John Doe" <sip:6010@192.168.30.254>;tag=12A542FD-68D9A80E
To: <sip:99057126386@192.168.30.254>
CSeq: 2 SUBSCRIBE
Call-ID: 16618e3a-f086df53-ab8784d4@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Accept: application/xpidf+xml,text/xml+msrtc.pidf
Authorization: Digest username="6010", realm="asterisk", nonce="650e592e", uri="sip:99057126386@192.168.30.254:5060", response="77630efa1d21bfc46421ed23a311a82e", algorithm=MD5
Max-Forwards: 70
Expires: 3600
Content-Length: 0


<------------->
--- (16 headers 0 lines) ---
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:16100 handle_request_subscribe: Got a new subscription 16618e3a-f086df53-ab8784d4@192.168.30.194 (possibly with auth)
Creating new subscription
Sending to 192.168.30.194 : 5060 (no NAT)
[Jan  7 09:07:14] DEBUG[10471]: chan_sip.c:8858 build_route: build_route: Retaining previous route: <sip:6010@192.168.30.194:5060>
Found peer '6010'
Looking for 99057126386 in default-local (domain 192.168.30.254)

<--- Transmitting (no NAT) to 192.168.30.194:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.30.194:5060;branch=z9hG4bKbb4a9c4725FD71E8;received=192.168.30.194
From: "John Doe" <sip:6010@192.168.30.254>;tag=12A542FD-68D9A80E
To: <sip:99057126386@192.168.30.254>;tag=as6d20257d
Call-ID: 16618e3a-f086df53-ab8784d4@192.168.30.194
CSeq: 2 SUBSCRIBE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


<------------>
[Jan  7 09:07:14] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:14] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4)
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4)
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #2 (no NAT) to 192.168.30.115:5060:
OPTIONS sip:6006@192.168.30.115:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4583448e;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as52ce1a12
To: <sip:6006@192.168.30.115:5060;transport=udp>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4df20db7381d07424046bfdd0ea7c889@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[13052]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #2 (no NAT) to 192.168.30.188:5060:
OPTIONS sip:6005@192.168.30.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK63adfd28;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as4ff1ea85
To: <sip:6005@192.168.30.188:5060>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 2feb981131b59c954034e0544a4b3a23@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 50 (2), at 192.168.30.85
[Jan  7 09:07:15] DEBUG[16612]: channel.c:4362 ast_generic_bridge: Got DTMF begin on channel (SIP/6003-0000002a)
[Jan  7 09:07:15] DEBUG[16612]: channel.c:4679 ast_channel_bridge: Bridge stops bridging channels SIP/6002-00000029 and SIP/6003-0000002a
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 50 (2), at 192.168.30.85
[Jan  7 09:07:15] DEBUG[16612]: channel.c:4362 ast_generic_bridge: Got DTMF end on channel (SIP/6003-0000002a)
[Jan  7 09:07:15] DEBUG[16612]: channel.c:4679 ast_channel_bridge: Bridge stops bridging channels SIP/6002-00000029 and SIP/6003-0000002a
[Jan  7 09:07:15] DEBUG[16612]: res_features.c:1482 feature_interpret: Feature interpret: chan=SIP/6002-00000029, peer=SIP/6003-0000002a, code=*2, sense=2, features=34, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-1000#tagcode-1001#tagcode-1002#tagcode-1003
[Jan  7 09:07:15] DEBUG[16612]: res_features.c:1398 feature_interpret_helper: Feature detected: fname=Attended Transfer sname=atxfer exten=*2
[Jan  7 09:07:15] DEBUG[16612]: res_features.c:1047 builtin_atxfer: Executing Attended Transfer SIP/6002-00000029, SIP/6003-0000002a (sense=2)
    -- Started music on hold, class 'default', on SIP/6002-00000029
    -- <SIP/6003-0000002a> Playing 'pbx-transfer' (language 'en')
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  7 09:07:15] DEBUG[12008]: channel.c:3167 set_format: Set channel SIP/6002-00000029 to write format slin
[Jan  7 09:07:15] DEBUG[12008]: res_musiconhold.c:261 ast_moh_files_next: SIP/6002-00000029 Opened file 3 '/var/lib/asterisk/moh//macroform-robot_dity'
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[13051]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #2 (no NAT) to 192.168.30.162:5060:
OPTIONS sip:6000@192.168.30.162:5060;line=95k0vvpm SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK582c46cd;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as5803c8ac
To: <sip:6000@192.168.30.162:5060;line=95k0vvpm>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4b471e254fae203f04f397954e234e60@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[13677]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:15] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #3 (no NAT) to 192.168.30.115:5060:
OPTIONS sip:6006@192.168.30.115:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4583448e;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as52ce1a12
To: <sip:6006@192.168.30.115:5060;transport=udp>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4df20db7381d07424046bfdd0ea7c889@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #3 (no NAT) to 192.168.30.188:5060:
OPTIONS sip:6005@192.168.30.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK63adfd28;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as4ff1ea85
To: <sip:6005@192.168.30.188:5060>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 2feb981131b59c954034e0544a4b3a23@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: channel.c:3167 set_format: Set channel SIP/6003-0000002a to write format slin
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 54 (6), at 192.168.30.85
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 54 (6), at 192.168.30.85
[Jan  7 09:07:16] DEBUG[16612]: channel.c:3167 set_format: Set channel SIP/6003-0000002a to write format ulaw
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 48 (0), at 192.168.30.85
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 48 (0), at 192.168.30.85
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[13056]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #3 (no NAT) to 192.168.30.162:5060:
OPTIONS sip:6000@192.168.30.162:5060;line=95k0vvpm SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK582c46cd;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as5803c8ac
To: <sip:6000@192.168.30.162:5060;line=95k0vvpm>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4b471e254fae203f04f397954e234e60@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 49 (1), at 192.168.30.85
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[13036]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 49 (1), at 192.168.30.85
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:16] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #4 (no NAT) to 192.168.30.115:5060:
OPTIONS sip:6006@192.168.30.115:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK4583448e;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as52ce1a12
To: <sip:6006@192.168.30.115:5060;transport=udp>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4df20db7381d07424046bfdd0ea7c889@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:3502 sip_destroy: Destroying SIP dialog 4df20db7381d07424046bfdd0ea7c889@192.168.30.254
[Jan  7 09:07:17] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6006
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6006
[Jan  7 09:07:17] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6006 - state 5 (Unavailable)
[Jan  7 09:07:17] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6006' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6006
[Jan  7 09:07:17] DEBUG[13057]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #4 (no NAT) to 192.168.30.188:5060:
OPTIONS sip:6005@192.168.30.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK63adfd28;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as4ff1ea85
To: <sip:6005@192.168.30.188:5060>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 2feb981131b59c954034e0544a4b3a23@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:3502 sip_destroy: Destroying SIP dialog 2feb981131b59c954034e0544a4b3a23@192.168.30.254
[Jan  7 09:07:17] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6005
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6005
[Jan  7 09:07:17] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6005 - state 5 (Unavailable)
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6005
[Jan  7 09:07:17] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6005' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[13043]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 48 (0), at 192.168.30.85
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:634 send_dtmf: Sending dtmf: 48 (0), at 192.168.30.85
[Jan  7 09:07:17] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:17] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable BRIDGEPEER.
[Jan  7 09:07:17] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jan  7 09:07:17] DEBUG[16612]: channel.c:3776 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan  7 09:07:17] DEBUG[16612]: channel.c:3771 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK.
[Jan  7 09:07:17] DEBUG[16612]: channel.c:2694 ast_indicate_data: Driver for channel 'SIP/6003-0000002a' does not support indication 3, emulating it
[Jan  7 09:07:17] DEBUG[16612]: channel.c:3167 set_format: Set channel SIP/6003-0000002a to write format slin
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6010@default-super:1] Set("Local/6010@default-super-ae64,2", "__PICKUPMARK=6010") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '4'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [6010@default-super:2] GotoIf("Local/6010@default-super-ae64,2", "0?4") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:6100 pbx_builtin_gotoif: Not taking any branch
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:735 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6003'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6010@default-super:3] Set("Local/6010@default-super-ae64,2", "GROUP(OUTGOING)=6003") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6010@default-super:4] Set("Local/6010@default-super-ae64,2", "OUTBOUND_GROUP_ONCE=6010@INCOMING") in new stack
[Jan  7 09:07:17] DEBUG[16612]: rtp.c:2725 ast_rtp_raw_write: Difference is 9896, ms is 1257
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6010@default-super:5] Set("Local/6010@default-super-ae64,2", "GROUPCOUNT=0") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6010@default-super:6] Set("Local/6010@default-super-ae64,2", "GROUPCOUNT2=0") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [6010@default-super:7] Set("Local/6010@default-super-ae64,2", "SCOPSERV_DBPUT(default/wrapup/6010/lastcall)=1262873237.85") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1262873237.85'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'default/wrapup/6010/lastcall'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Macro'
    -- Executing [6010@default-super:8] Macro("Local/6010@default-super-ae64,2", "default-dial|SIP/6010|6010|default|20|en|b6010@default|twWxXkK||default||Local/0@default-local/n|disa") in new stack
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6003'
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is ''
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-default-dial:1] NoOp("Local/6010@default-super-ae64,2", ""CALL TO LOCAL EXTENSION FROM 6003()"") in new stack
[Jan  7 09:07:17] DEBUG[16655]: app_macro.c:379 _macro_exec: Executed application: NoOp
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-default-dial:2] Set("Local/6010@default-super-ae64,2", "__PICKUPMARK=6010") in new stack
[Jan  7 09:07:17] DEBUG[16655]: app_macro.c:379 _macro_exec: Executed application: Set
[Jan  7 09:07:17] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'AGI'
    -- Executing [s@macro-default-dial:3] AGI("Local/6010@default-super-ae64,2", "agi://127.0.0.1:4573/dial") in new stack
AGI Tx >> agi_network: yes
AGI Tx >> agi_network_script: dial
AGI Tx >> agi_request: agi://127.0.0.1:4573/dial
AGI Tx >> agi_channel: Local/6010@default-super-ae64,2
AGI Tx >> agi_language: en
AGI Tx >> agi_type: Local
AGI Tx >> agi_uniqueid: 1262873237.85
AGI Tx >> agi_callerid: 6003
AGI Tx >> agi_calleridname: unknown
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: unknown
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-default-dial
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
[Jan  7 09:07:17] DEBUG[13055]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:17] DEBUG[13047]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:17] DEBUG[16657]: manager.c:2233 process_message: Manager received command 'login'
  == Parsing '/etc/asterisk/manager.conf': [Jan  7 09:07:17] DEBUG[16657]: config.c:895 config_text_file_load: Parsing /etc/asterisk/manager.conf
Found
[Jan  7 09:07:17] DEBUG[16657]: acl.c:355 ast_append_ha: 127.0.0.1/255.255.255.255 appended to acl for peer
[Jan  7 09:07:17] DEBUG[16657]: acl.c:370 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.1
AGI Rx << GET VARIABLE ARG1
AGI Tx >> 200 result=1 (SIP/6010)
AGI Rx << GET VARIABLE ARG2
AGI Tx >> 200 result=1 (6010)
AGI Rx << GET VARIABLE ARG3
AGI Tx >> 200 result=1 (default)
AGI Rx << GET VARIABLE ARG4
AGI Tx >> 200 result=1 (20)
AGI Rx << GET VARIABLE ARG5
AGI Tx >> 200 result=1 (en)
AGI Rx << GET VARIABLE ARG6
AGI Tx >> 200 result=1 (b6010@default)
AGI Rx << GET VARIABLE ARG7
AGI Tx >> 200 result=1 (twWxXkK)
AGI Rx << GET VARIABLE ARG8
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE ARG9
AGI Tx >> 200 result=1 (default)
AGI Rx << GET VARIABLE ARG10
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE ARG11
AGI Tx >> 200 result=1 (Local/0@default-local/n)
AGI Rx << GET VARIABLE ARG12
AGI Tx >> 200 result=1 (disa)
AGI Rx << GET VARIABLE EXT_ACCODE
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE MACRO_PRIORITY
AGI Tx >> 200 result=1 (8)
AGI Rx << GET VARIABLE CALLBACK_ON_HANGUP
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE EPICCALLID
AGI Tx >> 200 result=0
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
AGI Rx << GET VARIABLE INCOMINGLINE
AGI Tx >> 200 result=0
AGI Rx << SET VARIABLE CHANNEL(language) "en"
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE CHANNEL(musicclass) "default"
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE AUTO_RECORDING
AGI Tx >> 200 result=0
AGI Rx << SET VARIABLE TOUCH_MONITOR "1262873237.85"
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE TOUCH_MIXMONITOR "1262873237.85"
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE FORCE_RECORDING
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE LIMIT_IN_DEFAULT_6010
AGI Tx >> 200 result=1 (8)
AGI Rx << GET VARIABLE GROUPCOUNT
AGI Tx >> 200 result=1 (0)
AGI Rx << GET VARIABLE GROUPCOUNT2
AGI Tx >> 200 result=1 (0)
[Jan  7 09:07:17] DEBUG[16657]: manager.c:2233 process_message: Manager received command 'ExtensionState'
[Jan  7 09:07:17] DEBUG[16657]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
AGI Rx << EXEC NoOp STATUS: 0
    -- AGI Script Executing Application: (NoOp) Options: (STATUS:)
AGI Tx >> 200 result=0
AGI Rx << SET CALLERID "6003"<6003>
AGI Tx >> 200 result=1
AGI Rx << EXEC Dial SIP/6010|20|twWxXkKT|
    -- AGI Script Executing Application: (Dial) Options: (SIP/6010|20|twWxXkKT|)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:17371 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4798 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to Off
[Jan  7 09:07:17] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4244 sip_new: *** Our native formats are 0x4 (ulaw)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4245 sip_new: *** Joint capabilities are 0x0 (nothing)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4246 sip_new: *** Our capabilities are 0x1004 (ulaw|g722)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4247 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4249 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:4270 sip_new: This channel will not be able to handle video.
[Jan  7 09:07:17] DEBUG[16655]: rtp.c:1653 ast_rtp_make_compatible: Channel 'Local/6010@default-super-ae64,2' has no RTP, not doing anything
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable TOUCH_MIXMONITOR.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable TOUCH_MONITOR.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3771 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG12.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG11.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG10.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG9.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG8.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG7.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG6.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG5.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG4.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG3.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG2.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable GROUPCOUNT2.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable GROUPCOUNT.
[Jan  7 09:07:17] DEBUG[16655]: channel.c:3776 ast_channel_inherit_variables: Not copying variable TRANSFERERNAME.
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:3185 sip_call: Outgoing Call for 6010
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:3393 update_call_counter: Updating call counter for outgoing call
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:3470 update_call_counter: Call to peer '6010' is 1 out of 8
[Jan  7 09:07:17] DEBUG[16655]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:17] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 6 (Ringing)
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:17] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6010' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:3200 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:6957 add_sdp: ** Our capability: 0x1004 (ulaw|g722) Video flag: False
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:6958 add_sdp: ** Our prefcodec: 0x4 (ulaw)
Audio is at 192.168.30.254 port 18908
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x1000 (g722) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:7075 add_sdp: -- Done with adding codecs to SDP
[Jan  7 09:07:17] DEBUG[16655]: chan_sip.c:7184 add_sdp: Done building SDP. Settling with this capability: 0x1004 (ulaw|g722)
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
INVITE sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK72124c35;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>
Contact: <sip:6003@192.168.30.254>
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
CSeq: 102 INVITE
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Remote-Party-ID: "6003" <sip:6003@192.168.30.254>;privacy=off;screen=no
Date: Thu, 07 Jan 2010 14:07:17 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Type: application/sdp
Content-Length: 268

v=0
o=root 10449 10449 IN IP4 192.168.30.254
s=session
c=IN IP4 192.168.30.254
t=0 0
m=audio 18908 RTP/AVP 0 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session f8647872-97369e4b-bbdcb68c@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK31d01ef4;rport
From: <sip:6010@192.168.30.254>;tag=as363aec27
To: "John Doe" <sip:6010@192.168.30.254>;tag=95483575-6EADD946
Contact: <sip:6010@192.168.30.254>
Call-ID: f8647872-97369e4b-bbdcb68c@192.168.30.194
CSeq: 117 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6010">
<address uri="sip:6010@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6010[default-local] new state Ringing for Notify User 6010
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 225ae379-926514c8-71992d47@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK42f92462;rport
From: <sip:6010@192.168.30.254>;tag=as15a79d07
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=DFA0B3F6-E631DFD5
Contact: <sip:6010@192.168.30.254>
Call-ID: 225ae379-926514c8-71992d47@192.168.30.190
CSeq: 139 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
vent: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6010">
<address uri="sip:6010@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6010[default-local] new state Ringing for Notify User 6002
    -- Called 6010
[Jan  7 09:07:17] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:17] DEBUG[10456]: manager.c:2233 process_message: Manager received command 'GetVar'
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK72124c35;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>;tag=5A3F7BB-49FF017C
CSeq: 102 INVITE
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
Contact: <sip:6010@192.168.30.194:5060>
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (10 headers 0 lines) ---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:2313 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254' Request 102: Found
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK42f92462;rport
From: <sip:6010@192.168.30.254>;tag=as15a79d07
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=DFA0B3F6-E631DFD5
CSeq: 139 NOTIFY
Call-ID: 225ae379-926514c8-71992d47@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 139
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '225ae379-926514c8-71992d47@192.168.30.190' of Request 139: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
Retransmitting #4 (no NAT) to 192.168.30.162:5060:
OPTIONS sip:6000@192.168.30.162:5060;line=95k0vvpm SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK582c46cd;rport
From: "asterisk" <sip:asterisk@192.168.30.254>;tag=as5803c8ac
To: <sip:6000@192.168.30.162:5060;line=95k0vvpm>
Contact: <sip:asterisk@192.168.30.254>
Call-ID: 4b471e254fae203f04f397954e234e60@192.168.30.254
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Date: Thu, 07 Jan 2010 14:07:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:3502 sip_destroy: Destroying SIP dialog 4b471e254fae203f04f397954e234e60@192.168.30.254
[Jan  7 09:07:17] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6000
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6000
[Jan  7 09:07:17] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6000 - state 5 (Unavailable)
[Jan  7 09:07:17] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6000' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6000
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK31d01ef4;rport
From: <sip:6010@192.168.30.254>;tag=as363aec27
To: "John Doe" <sip:6010@192.168.30.254>;tag=95483575-6EADD946
CSeq: 117 NOTIFY
Call-ID: f8647872-97369e4b-bbdcb68c@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 117
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'f8647872-97369e4b-bbdcb68c@192.168.30.194' of Request 117: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK72124c35;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>;tag=5A3F7BB-49FF017C
CSeq: 102 INVITE
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
Contact: <sip:6010@192.168.30.194:5060>
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Allow-Events: talk,hold,conference
Accept-Language: en-us,en;q=0.9
Content-Length: 0


------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:17] DEBUG[10471]: chan_sip.c:2313 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254' Request 102: Found
[Jan  7 09:07:17] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:17] DEBUG[10453]: devicestate.c:287 do_state_change:     -- SIP/6010-0000002b is ringing
Changing state for SIP/6010 - state 6 (Ringing)
[Jan  7 09:07:17] DEBUG[16655]: rtp.c:1564 ast_rtp_early_bridge: Channel 'Local/6010@default-super-ae64,2' has no RTP, not doing anything
[Jan  7 09:07:17] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6010' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  7 09:07:17] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[13042]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:17] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[13051]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[13051]: manager.c:2233 process_message: Manager received command 'GetVar'
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[12008]: rtp.c:923 ast_rtcp_read: Got RTCP report of 104 bytes
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[13677]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:18] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[13052]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16612]: rtp.c:923 ast_rtcp_read: Got RTCP report of 104 bytes
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[13041]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[13056]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[13036]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK72124c35;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>;tag=5A3F7BB-49FF017C
CSeq: 102 INVITE
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
Contact: <sip:6010@192.168.30.194:5060>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Type: application/sdp
Content-Length: 203

v=0
o=- 1262873236 1262873236 IN IP4 192.168.30.194
s=Polycom IP Phone
c=IN IP4 192.168.30.194
t=0 0
m=audio 2232 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000

<------------->
--- (12 headers 9 lines) ---
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 102
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254' of Request 102: Match Found
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP o=- 1262873236 1262873236 IN IP4 192.168.30.194... UNSUPPORTED.
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED.
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP c=IN IP4 192.168.30.194... OK.
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5433 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
Found RTP audio format 0
Found RTP audio format 101
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
Found audio description format PCMU for ID 0
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
Found audio description format telephone-event for ID 101
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5571 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5596 process_sdp: T38 state changed to 0 on channel SIP/6010-0000002b
Capabilities: us - 0x1004 (ulaw|g722), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5624 process_sdp: Our T38 capability = (3856), peer T38 capability (0), joint T38 capability (3856)
Peer audio RTP is at port 192.168.30.194:2232
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:5729 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:3393 update_call_counter: Updating call counter for outgoing call
[Jan  7 09:07:19] DEBUG[10471]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:19] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 2 (In use)
[Jan  7 09:07:19] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6010' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session f8647872-97369e4b-bbdcb68c@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK2da35581;rport
From: <sip:6010@192.168.30.254>;tag=as363aec27
To: "John Doe" <sip:6010@192.168.30.254>;tag=95483575-6EADD946
Contact: <sip:6010@192.168.30.254>
Call-ID: f8647872-97369e4b-bbdcb68c@192.168.30.194
CSeq: 118 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6010">
<address uri="sip:6010@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6010[default-local] new state InUse for Notify User 6010
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 225ae379-926514c8-71992d47@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK090f7f53;rport
From: <sip:6010@192.168.30.254>;tag=as15a79d07
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=DFA0B3F6-E631DFD5
Contact: <sip:6010@192.168.30.254>
Call-ID: 225ae379-926514c8-71992d47@192.168.30.190
CSeq: 140 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 353

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6010">
<address uri="sip:6010@192.168.30.254;user=ip" priority="0.800000">
<status status="inuse" />
<msnsubstatus substatus="onthephone" />
</address>
</atom>
</presence>

---
 Extension Changed 6010[default-local] new state InUse for Notify User 6002
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:8920 build_route: build_route: Contact hop: <sip:6010@192.168.30.194:5060>
list_route: hop: <sip:6010@192.168.30.194:5060>
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:6466 reqprep: Strict routing enforced for session 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Transmitting (no NAT) to 192.168.30.194:5060:
ACK sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK713c7c94;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>;tag=5A3F7BB-49FF017C
Contact: <sip:6003@192.168.30.254>
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
CSeq: 102 ACK
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Remote-Party-ID: "6003" <sip:6003@192.168.30.254>;privacy=off;screen=no
Content-Length: 0


---
[Jan  7 09:07:19] DEBUG[16655]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
    -- SIP/6010-0000002b answered Local/6010@default-super-ae64,2
[Jan  7 09:07:19] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 2 (In use)
[Jan  7 09:07:19] DEBUG[16655]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-super
[Jan  7 09:07:19] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:19] DEBUG[10453]: chan_local.c:146 local_devicestate: Checking if extension 6010@default-super exists (devicestate)
[Jan  7 09:07:19] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-super - state 2 (In use)
[Jan  7 09:07:19] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6010' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:19] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'Local/6010@default-super' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:19] DEBUG[16655]: rtp.c:2898 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan  7 09:07:19] DEBUG[16655]: rtp.c:2915 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK2da35581;rport
From: <sip:6010@192.168.30.254>;tag=as363aec27
To: "John Doe" <sip:6010@192.168.30.254>;tag=95483575-6EADD946
CSeq: 118 NOTIFY
Call-ID: f8647872-97369e4b-bbdcb68c@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 118
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'f8647872-97369e4b-bbdcb68c@192.168.30.194' of Request 118: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK090f7f53;rport
From: <sip:6010@192.168.30.254>;tag=as15a79d07
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=DFA0B3F6-E631DFD5
CSeq: 140 NOTIFY
Call-ID: 225ae379-926514c8-71992d47@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 140
[Jan  7 09:07:19] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '225ae379-926514c8-71992d47@192.168.30.190' of Request 140: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:19] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:20] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:20] DEBUG[16616]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x9632f94 was pretty quick last time, waiting for them.
[Jan  7 09:07:20] DEBUG[16655]: channel.c:3709 ast_channel_masquerade: Planning to masquerade channel SIP/6010-0000002b into the structure of Local/6010@default-super-ae64,1
[Jan  7 09:07:20] DEBUG[16655]: channel.c:3723 ast_channel_masquerade: Done planning to masquerade channel SIP/6010-0000002b into the structure of Local/6010@default-super-ae64,1
[Jan  7 09:07:20] DEBUG[16655]: chan_local.c:339 local_write: Not posting to queue since already masked on 'Local/6010@default-super-ae64,2'
[Jan  7 09:07:20] DEBUG[16612]: channel.c:3864 ast_do_masquerade: Got clone lock for masquerade on 'SIP/6010-0000002b' at 0x9649ab8
[Jan  7 09:07:20] DEBUG[16612]: channel.c:4050 ast_do_masquerade: Putting channel SIP/6010-0000002b in 4/4 formats
[Jan  7 09:07:20] DEBUG[16612]: chan_sip.c:4017 sip_fixup: SIP Fixup: New owner for dialogue 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254: SIP/6010-0000002b (Old parent: Local/6010@default-super-ae64,1<ZOMBIE>)
[Jan  7 09:07:20] DEBUG[16612]: channel.c:4098 ast_do_masquerade: Released clone lock on 'Local/6010@default-super-ae64,1<ZOMBIE>'
[Jan  7 09:07:20] DEBUG[16612]: channel.c:4108 ast_do_masquerade: Done Masquerading SIP/6010-0000002b (6)
[Jan  7 09:07:20] DEBUG[16612]: channel.c:3167 set_format: Set channel SIP/6003-0000002a to write format ulaw
[Jan  7 09:07:20] DEBUG[16655]: channel.c:4312 ast_generic_bridge: Didn't get a frame from channel: Local/6010@default-super-ae64,1<ZOMBIE>
[Jan  7 09:07:20] DEBUG[16655]: channel.c:4679 ast_channel_bridge: Bridge stops bridging channels Local/6010@default-super-ae64,2 and Local/6010@default-super-ae64,1<ZOMBIE>
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'ResetCDR'
    -- Executing [h@macro-default-dial:1] ResetCDR("Local/6010@default-super-ae64,2", "w") in new stack
[Jan  7 09:07:20] DEBUG[16612]: channel.c:1565 ast_hangup: Hanging up channel 'SIP/6010-0000002b'
[Jan  7 09:07:20] DEBUG[16612]: chan_sip.c:3710 sip_hangup: Hangup call SIP/6010-0000002b, SIP callid 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254)
[Jan  7 09:07:20] DEBUG[16612]: chan_sip.c:3719 sip_hangup: update_call_counter(6010) - decrement call limit counter on hangup
[Jan  7 09:07:20] DEBUG[16612]: chan_sip.c:3393 update_call_counter: Updating call counter for outgoing call
[Jan  7 09:07:20] DEBUG[16612]: chan_sip.c:3444 update_call_counter: Call to peer '6010' removed from call limit 8
[Jan  7 09:07:20] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:20] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 1 (Not in use)
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session f8647872-97369e4b-bbdcb68c@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK1feb145e;rport
From: <sip:6010@192.168.30.254>;tag=as363aec27
To: "John Doe" <sip:6010@192.168.30.254>;tag=95483575-6EADD946
Contact: <sip:6010@192.168.30.254>
Call-ID: f8647872-97369e4b-bbdcb68c@192.168.30.194
CSeq: 119 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 348

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6010">
<address uri="sip:6010@192.168.30.254;user=ip" priority="0.800000">
<status status="open" />
<msnsubstatus substatus="online" />
</address>
</atom>
</presence>

---
 Extension Changed 6010[default-local] new state Idle for Notify User 6010
[Jan  7 09:07:20] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6010' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Scheduling destruction of SIP dialog '0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254' in 6400 ms (Method: INVITE)
[Jan  7 09:07:20] DEBUG[16612]: chan_sip.c:6466 reqprep: Strict routing enforced for session 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
[Jan  7 09:07:20] DEBUG[16655]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: inserting a CDR record.
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
BYE sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK70ca1e8a;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>;tag=5A3F7BB-49FF017C
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
CSeq: 103 BYE
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Remote-Party-ID: "6003" <sip:6003@192.168.30.254>;privacy=off;screen=no
X-Asterisk-HangupCause: Unknown
X-Asterisk-HangupCauseCode: 0
Content-Length: 0


---
[Jan  7 09:07:20] DEBUG[16655]: cdr_addon_mysql.c:245 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr_pre (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-01-07 09:07:17','\"6003\" <6003>','6003','6010','default-super', 'Local/6010@default-super-ae64,2','SIP/6010-0000002b','Dial','SIP/6010|20|twWxXkKT|',3,1,'ANSWERED',3,'','1262873237.85','')
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 225ae379-926514c8-71992d47@192.168.30.190
[Jan  7 09:07:20] DEBUG[16655]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded!
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '"6003" <6003>'
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK0fe686e0;rport
From: <sip:6010@192.168.30.254>;tag=as15a79d07
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=DFA0B3F6-E631DFD5
Contact: <sip:6010@192.168.30.254>
Call-ID: 225ae379-926514c8-71992d47@192.168.30.190
CSeq: 141 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 348

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6010">
<address uri="sip:6010@192.168.30.254;user=ip" priority="0.800000">
<status status="open" />
<msnsubstatus substatus="online" />
</address>
</atom>
</presence>

---
 Extension Changed 6010[default-local] new state Idle for Notify User 6002
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK1feb145e;rport
From: <sip:6010@192.168.30.254>;tag=as363aec27
To: "John Doe" <sip:6010@192.168.30.254>;tag=95483575-6EADD946
CSeq: 119 NOTIFY
Call-ID: f8647872-97369e4b-bbdcb68c@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
Function result is '6003'
--- (11 headers 0 lines) ---
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6010'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'default-super'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'Local/6010@default-super-ae64,2'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'SIP/6010-0000002b'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'SIP/6010|20|twWxXkKT|'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:17'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:19'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:20'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '3'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1262873237.85'
[Jan  7 09:07:20] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 119
[Jan  7 09:07:20] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'f8647872-97369e4b-bbdcb68c@192.168.30.194' of Request 119: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'NoCDR'
    -- Executing [h@macro-default-dial:2] NoCDR("Local/6010@default-super-ae64,2", "") in new stack
[Jan  7 09:07:20] DEBUG[16612]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: inserting a CDR record.

<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK0fe686e0;rport
From: <sip:6010@192.168.30.254>;tag=as15a79d07
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=DFA0B3F6-E631DFD5
CSeq: 141 NOTIFY
Call-ID: 225ae379-926514c8-71992d47@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:20] DEBUG[16612]: cdr_addon_mysql.c:245 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr_pre (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-01-07 09:07:17','','','s','default-super', 'SIP/6010-0000002b','','','',3,1,'ANSWERED',3,'','1262873237.86','')
[Jan  7 09:07:20] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 141
[Jan  7 09:07:20] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '225ae379-926514c8-71992d47@192.168.30.190' of Request 141: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
[Jan  7 09:07:20] DEBUG[16612]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded!
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 's'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'default-super'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'SIP/6010-0000002b'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:1861 pbx_extension_helper: Launching 'DeadAGI'
    -- Executing [h@macro-default-dial:3] DeadAGI("Local/6010@default-super-ae64,2", "agi://127.0.0.1:4573/cdr?arg1=1262873237.85") in new stack
AGI Tx >> agi_network: yes
AGI Tx >> agi_network_script: cdr?arg1=1262873237.85
AGI Tx >> agi_request: agi://127.0.0.1:4573/cdr?arg1=1262873237.85
AGI Tx >> agi_channel: Local/6010@default-super-ae64,2
AGI Tx >> agi_language: en
AGI Tx >> agi_type: Local
AGI Tx >> agi_uniqueid: 1262873237.85
AGI Tx >> agi_callerid: 6003
AGI Tx >> agi_calleridname: 6003
AGI Tx >> agi_callingpres: 0
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK70ca1e8a;rport
From: "6003" <sip:6003@192.168.30.254>;tag=as102eea44
To: <sip:6010@192.168.30.194:5060>;tag=5A3F7BB-49FF017C
CSeq: 103 BYE
Call-ID: 0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254
Contact: <sip:6010@192.168.30.194:5060>
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (10 headers 0 lines) ---
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: unknown
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-default-dial
AGI Tx >> agi_extension: h
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:17'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:19'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:20'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '3'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1262873237.86'
[Jan  7 09:07:20] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:20] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
    -- Stopped music on hold on SIP/6002-00000029
[Jan  7 09:07:20] DEBUG[16612]: channel.c:3167 set_format: Set channel SIP/6002-00000029 to write format ulaw
[Jan  7 09:07:20] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '0bcb63c9239afc65178ea15d1f8703f6@192.168.30.254' of Request 103: Match Found
[Jan  7 09:07:20] DEBUG[13057]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:20] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 1 (Not in use)
[Jan  7 09:07:20] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6010
[Jan  7 09:07:20] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6010' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
    -- <SIP/6003-0000002a> Playing 'pbx-invalid' (language 'en')
    -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1262873237.85 completed, returning 0
[Jan  7 09:07:20] DEBUG[16655]: channel.c:1570 ast_hangup: Hanging up zombie 'Local/6010@default-super-ae64,1<ZOMBIE>'
[Jan  7 09:07:20] DEBUG[16655]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-super
[Jan  7 09:07:20] DEBUG[16655]: rtp.c:1564 ast_rtp_early_bridge: Channel 'Local/6010@default-super-ae64,2' has no RTP, not doing anything
[Jan  7 09:07:20] DEBUG[16655]: app_dial.c:1929 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
AGI Tx >> 200 result=-1
[Jan  7 09:07:20] DEBUG[16655]: res_agi.c:1925 run_agi: Local/6010@default-super-ae64,2 hungup
[Jan  7 09:07:20] DEBUG[16655]: app_macro.c:372 _macro_exec: Spawn extension (macro-default-dial,s,3) exited non-zero on 'Local/6010@default-super-ae64,2' in macro 'default-dial'
[Jan  7 09:07:20] DEBUG[16655]: pbx.c:2411 __ast_pbx_run: Spawn extension (default-super,6010,8) exited non-zero on 'Local/6010@default-super-ae64,2'
  == Spawn extension (default-super, 6010, 8) exited non-zero on 'Local/6010@default-super-ae64,2'
[Jan  7 09:07:20] DEBUG[16655]: channel.c:1462 ast_softhangup_nolock: Soft-Hanging up channel 'Local/6010@default-super-ae64,2'
[Jan  7 09:07:20] DEBUG[16655]: channel.c:1565 ast_hangup: Hanging up channel 'Local/6010@default-super-ae64,2'
[Jan  7 09:07:20] DEBUG[16655]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-super
[Jan  7 09:07:20] DEBUG[10453]: chan_local.c:146 local_devicestate: Checking if extension 6010@default-super exists (devicestate)
[Jan  7 09:07:20] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-super - state 1 (Not in use)
[Jan  7 09:07:20] DEBUG[10453]: chan_local.c:146 local_devicestate: Checking if extension 6010@default-super exists (devicestate)
[Jan  7 09:07:20] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-super - state 1 (Not in use)
[Jan  7 09:07:20] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'Local/6010@default-super' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:20] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'Local/6010@default-super' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:20] DEBUG[13043]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:20] DEBUG[13055]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:20] DEBUG[13047]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:20] DEBUG[13042]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:21] DEBUG[13051]: manager.c:2233 process_message: Manager received command 'Ping'
lab*CLI>
<--- SIP read from 192.168.30.85:5060 --->
BYE sip:6002@192.168.30.254 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.85:5060;branch=z9hG4bK6e80596b95238E9C
From: <sip:6003@192.168.30.85:5060>;tag=319B8481-11CA4822
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
CSeq: 1 BYE
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
Contact: <sip:6003@192.168.30.85:5060>
User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Max-Forwards: 70
Content-Length: 0

lab*CLI>
<------------->
--- (11 headers 0 lines) ---
Sending to 192.168.30.85 : 5060 (no NAT)
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:1719 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:16049 handle_request_bye: Received bye, issuing owner hangup
lab*CLI>
<--- Transmitting (no NAT) to 192.168.30.85:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.85:5060;branch=z9hG4bK6e80596b95238E9C;received=192.168.30.85
From: <sip:6003@192.168.30.85:5060>;tag=319B8481-11CA4822
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=as662ee00b
Call-ID: 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254
CSeq: 1 BYE
User-Agent: Asterisk PBX (asterisk)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


------------>
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'ResetCDR'
    -- Executing [h@macro-default-dial:1] ResetCDR("SIP/6002-00000029", "w") in new stack
[Jan  7 09:07:21] DEBUG[16612]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: inserting a CDR record.
[Jan  7 09:07:21] DEBUG[16612]: cdr_addon_mysql.c:245 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr_pre (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-01-07 09:07:12','\"Reception 6002\" <6002>','6002','6003','default-super', 'SIP/6002-00000029','SIP/6003-0000002a','ResetCDR','w',9,7,'ANSWERED',3,'6002','1262873232.82','')
[Jan  7 09:07:21] DEBUG[16612]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded!
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '"Reception 6002" <6002>'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6002'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6003'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'default-super'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'SIP/6002-00000029'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'SIP/6003-0000002a'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'ResetCDR'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'w'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:12'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:14'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '2010-01-07 09:07:21'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '9'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '7'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '6002'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1262873232.82'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'NoCDR'
    -- Executing [h@macro-default-dial:2] NoCDR("SIP/6002-00000029", "") in new stack
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'DeadAGI'
    -- Executing [h@macro-default-dial:3] DeadAGI("SIP/6002-00000029", "agi://127.0.0.1:4573/cdr?arg1=1262873232.82") in new stack
AGI Tx >> agi_network: yes
AGI Tx >> agi_network_script: cdr?arg1=1262873232.82
AGI Tx >> agi_request: agi://127.0.0.1:4573/cdr?arg1=1262873232.82
AGI Tx >> agi_channel: SIP/6002-00000029
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1262873232.82
AGI Tx >> agi_callerid: 6002
AGI Tx >> agi_calleridname: Reception 6002
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 6003
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-default-dial
AGI Tx >> agi_extension: h
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode: 6002
AGI Tx >>
    -- AGI Script agi://127.0.0.1:4573/cdr?arg1=1262873232.82 completed, returning 0
[Jan  7 09:07:21] DEBUG[16612]: channel.c:1565 ast_hangup: Hanging up channel 'SIP/6003-0000002a'
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3710 sip_hangup: Hangup call SIP/6003-0000002a, SIP callid 2bd50d2e499d579d4df3c9d8438b8584@192.168.30.254)
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3719 sip_hangup: update_call_counter(6003) - decrement call limit counter on hangup
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3393 update_call_counter: Updating call counter for outgoing call
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3444 update_call_counter: Call to peer '6003' removed from call limit 4
[Jan  7 09:07:21] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6003
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:21] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6003
[Jan  7 09:07:21] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6003 - state 1 (Not in use)
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session b9119199-1a151d0a-bc1ce6a3@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK729075bf;rport
From: <sip:6003@192.168.30.254>;tag=as0a78822f
To: "John Doe" <sip:6010@192.168.30.254>;tag=30FD18A4-1FBC974D
Contact: <sip:6003@192.168.30.254>
Call-ID: b9119199-1a151d0a-bc1ce6a3@192.168.30.194
CSeq: 117 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 348

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6003">
<address uri="sip:6003@192.168.30.254;user=ip" priority="0.800000">
<status status="open" />
<msnsubstatus substatus="online" />
</address>
</atom>
</presence>

---
 Extension Changed 6003[default-local] new state Idle for Notify User 6010
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 7eb1fb08-f5556787-ddf48236@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK3b4a4f83;rport
From: <sip:6003@192.168.30.254>;tag=as2b2192a7
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=F9398215-2D9A4E24
Contact: <sip:6003@192.168.30.254>
Call-ID: 7eb1fb08-f5556787-ddf48236@192.168.30.190
CSeq: 151 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 348

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6003">
<address uri="sip:6003@192.168.30.254;user=ip" priority="0.800000">
<status status="open" />
<msnsubstatus substatus="online" />
</address>
</atom>
</presence>

---
 Extension Changed 6003[default-local] new state Idle for Notify User 6002
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:21] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6003 - state 1 (Not in use)
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6003
[Jan  7 09:07:21] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:21] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:21] DEBUG[16612]: rtp.c:1572 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Jan  7 09:07:21] DEBUG[16612]: app_dial.c:1929 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
AGI Tx >> 200 result=-1
[Jan  7 09:07:21] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
AGI Rx << GET VARIABLE DIALSTATUS
AGI Tx >> 200 result=1 (ANSWER)
[Jan  7 09:07:21] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:21] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK729075bf;rport
From: <sip:6003@192.168.30.254>;tag=as0a78822f
To: "John Doe" <sip:6010@192.168.30.254>;tag=30FD18A4-1FBC974D
CSeq: 117 NOTIFY
Call-ID: b9119199-1a151d0a-bc1ce6a3@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 117
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'b9119199-1a151d0a-bc1ce6a3@192.168.30.194' of Request 117: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived

<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK3b4a4f83;rport
From: <sip:6003@192.168.30.254>;tag=as2b2192a7
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=F9398215-2D9A4E24
CSeq: 151 NOTIFY
Call-ID: 7eb1fb08-f5556787-ddf48236@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 151
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '7eb1fb08-f5556787-ddf48236@192.168.30.190' of Request 151: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
    -- AGI Script agi://127.0.0.1:4573/dial completed, returning 0
[Jan  7 09:07:21] DEBUG[16612]: app_macro.c:379 _macro_exec: Executed application: AGI
[Jan  7 09:07:21] DEBUG[16616]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x9632f94
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [6003@default-super:9] GotoIf("SIP/6002-00000029", "1?10:13") in new stack
    -- Goto (default-super,6003,10)
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [6003@default-super:10] GotoIf("SIP/6002-00000029", "1?12:11") in new stack
    -- Goto (default-super,6003,12)
[Jan  7 09:07:21] DEBUG[13677]: manager.c:2233 process_message: Manager received command 'Ping'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '16'
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:1861 pbx_extension_helper: Launching 'Hangup'
    -- Executing [6003@default-super:12] Hangup("SIP/6002-00000029", "16") in new stack
[Jan  7 09:07:21] DEBUG[16612]: pbx.c:2411 __ast_pbx_run: Spawn extension (default-super,6003,12) exited non-zero on 'SIP/6002-00000029'
  == Spawn extension (default-super, 6003, 12) exited non-zero on 'SIP/6002-00000029'
[Jan  7 09:07:21] DEBUG[16612]: channel.c:1462 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/6002-00000029'
[Jan  7 09:07:21] DEBUG[16612]: channel.c:1565 ast_hangup: Hanging up channel 'SIP/6002-00000029'
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3710 sip_hangup: Hangup call SIP/6002-00000029, SIP callid 93c63026-5e56f305-5c3cf214@192.168.30.190)
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3719 sip_hangup: update_call_counter(6002) - decrement call limit counter on hangup
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3393 update_call_counter: Updating call counter for incoming call
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:3444 update_call_counter: Call from peer '6002' removed from call limit 8
[Jan  7 09:07:21] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002
Scheduling destruction of SIP dialog '93c63026-5e56f305-5c3cf214@192.168.30.190' in 32000 ms (Method: ACK)
[Jan  7 09:07:21] DEBUG[16612]: chan_sip.c:6466 reqprep: Strict routing enforced for session 93c63026-5e56f305-5c3cf214@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
BYE sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK12053895;rport
From: <sip:6003@192.168.30.254;user=phone>;tag=as57fed4ba
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
CSeq: 102 BYE
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[Jan  7 09:07:21] DEBUG[16612]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002
  == MixMonitor close filestream
  == End MixMonitor Recording SIP/6002-00000029
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:21] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 1 (Not in use)
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session b94398ca-9c3d9863-872b7064@192.168.30.194
set_destination: Parsing <sip:6010@192.168.30.194:5060> for address/port to send to
set_destination: set destination to 192.168.30.194, port 5060
Reliably Transmitting (no NAT) to 192.168.30.194:5060:
NOTIFY sip:6010@192.168.30.194:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK2f45e6e7;rport
From: <sip:6002@192.168.30.254>;tag=as3ac6d3c7
To: "John Doe" <sip:6010@192.168.30.254>;tag=E555850D-9395049E
Contact: <sip:6002@192.168.30.254>
Call-ID: b94398ca-9c3d9863-872b7064@192.168.30.194
CSeq: 112 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 348

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6010@192.168.30.254;method=SUBSCRIBE" />
<atom id="6002">
<address uri="sip:6002@192.168.30.254;user=ip" priority="0.800000">
<status status="open" />
<msnsubstatus substatus="online" />
</address>
</atom>
</presence>

---
 Extension Changed 6002[default-local] new state Idle for Notify User 6010
[Jan  7 09:07:21] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:6466 reqprep: Strict routing enforced for session 439ba601-121a2dd0-186b64cf@192.168.30.190
set_destination: Parsing <sip:6002@192.168.30.190:5060> for address/port to send to
set_destination: set destination to 192.168.30.190, port 5060
Reliably Transmitting (no NAT) to 192.168.30.190:5060:
NOTIFY sip:6002@192.168.30.190:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK474a2cb7;rport
From: <sip:6002@192.168.30.254>;tag=as25231e62
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=49E351FE-54EAAC5D
Contact: <sip:6002@192.168.30.254>
Call-ID: 439ba601-121a2dd0-186b64cf@192.168.30.190
CSeq: 140 NOTIFY
User-Agent: Asterisk PBX (asterisk)
Max-Forwards: 70
Event: presence
Content-Type: application/xpidf+xml
Subscription-State: active
Content-Length: 348

<?xml version="1.0"?>
<!DOCTYPE presence PUBLIC "-//IETF//DTD RFCxxxx XPIDF 1.0//EN" "xpidf.dtd">
<presence>
<presentity uri="sip:6002@192.168.30.254;method=SUBSCRIBE" />
<atom id="6002">
<address uri="sip:6002@192.168.30.254;user=ip" priority="0.800000">
<status status="open" />
<msnsubstatus substatus="online" />
</address>
</atom>
</presence>

---
 Extension Changed 6002[default-local] new state Idle for Notify User 6002
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:21] DEBUG[10453]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 1 (Not in use)
[Jan  7 09:07:21] DEBUG[10453]: chan_sip.c:17295 sip_devicestate: Checking device state for peer 6002
[Jan  7 09:07:21] DEBUG[10503]: app_queue.c:701 handle_statechange: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK12053895;rport
From: <sip:6003@192.168.30.254;user=phone>;tag=as57fed4ba
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=1A03C453-A780B0C2
CSeq: 102 BYE
Call-ID: 93c63026-5e56f305-5c3cf214@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (10 headers 0 lines) ---
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '93c63026-5e56f305-5c3cf214@192.168.30.190' of Request 102: Match Found
SIP Response message for INCOMING dialog BYE arrived
lab*CLI>
<--- SIP read from 192.168.30.194:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK2f45e6e7;rport
From: <sip:6002@192.168.30.254>;tag=as3ac6d3c7
To: "John Doe" <sip:6010@192.168.30.254>;tag=E555850D-9395049E
CSeq: 112 NOTIFY
Call-ID: b94398ca-9c3d9863-872b7064@192.168.30.194
Contact: <sip:6010@192.168.30.194:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 112
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on 'b94398ca-9c3d9863-872b7064@192.168.30.194' of Request 112: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived
lab*CLI>
<--- SIP read from 192.168.30.190:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.30.254:5060;branch=z9hG4bK474a2cb7;rport
From: <sip:6002@192.168.30.254>;tag=as25231e62
To: "Reception 6002" <sip:6002@192.168.30.254>;tag=49E351FE-54EAAC5D
CSeq: 140 NOTIFY
Call-ID: 439ba601-121a2dd0-186b64cf@192.168.30.190
Contact: <sip:6002@192.168.30.190:5060>
Event: presence
User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.1.3.0439
Accept-Language: en-us,en;q=0.9
Content-Length: 0


<------------->
--- (11 headers 0 lines) ---
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2239 __sip_ack: Acked pending invite 140
[Jan  7 09:07:21] DEBUG[10471]: chan_sip.c:2271 __sip_ack: Stopping retransmission on '439ba601-121a2dd0-186b64cf@192.168.30.190' of Request 140: Match Found
SIP Response message for INCOMING dialog NOTIFY arrived