[Jul 18 15:15:04] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Queue'
    -- Executing [new@sub-queues:11] Queue("SIP/ss1tampa.mixnetworks.com-084ac6c0", "xfertest_CQ_39|n") in new stack
[Jul 18 15:15:04] DEBUG[4315]: app_queue.c:3362 queue_exec: NO QUEUE_PRIO variable found. Using default.
[Jul 18 15:15:04] DEBUG[4315]: app_queue.c:3385 queue_exec: queue: xfertest_CQ_39, options: n, url: (null), announce: (null), expires: 0, priority: 0
[Jul 18 15:15:04] DEBUG[4315]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest
[Jul 18 15:15:04] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/ss1tampa.mixnetworks.com - state 4 (Invalid)
[Jul 18 15:15:04] DEBUG[4316]: app_queue.c:547 changethread: Device 'SIP/ss1tampa.mixnetworks.com' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul 18 15:15:04] DEBUG[4315]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:15:04] DEBUG[4315]: app_queue.c:710 add_to_interfaces: Adding SIP/u301#xfertest to the list of interfaces that make up all of our queue members.
[Jul 18 15:15:04] DEBUG[4315]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u302#xfertest
[Jul 18 15:15:04] DEBUG[4315]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest
[Jul 18 15:15:04] DEBUG[4315]: app_queue.c:710 add_to_interfaces: Adding SIP/u302#xfertest to the list of interfaces that make up all of our queue members.
[Jul 18 15:15:04] DEBUG[4315]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u303#xfertest
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u303#xfertest
[Jul 18 15:15:05] DEBUG[4315]: app_queue.c:710 add_to_interfaces: Adding SIP/u303#xfertest to the list of interfaces that make up all of our queue members.
[Jul 18 15:15:05] DEBUG[4315]: app_queue.c:1225 join_queue: Queue 'xfertest_CQ_39' Join, Channel 'SIP/ss1tampa.mixnetworks.com-084ac6c0', Position '1'
[Jul 18 15:15:05] DEBUG[4315]: channel.c:2727 ast_prod: Prodding channel 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6499 transmit_response_with_sdp: Setting framing from config on incoming call
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
    -- Started music on hold, class 'default', on SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:05] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
[Jul 18 15:15:05] DEBUG[4315]: app_queue.c:2116 is_our_turn: It's our turn (SIP/ss1tampa.mixnetworks.com-084ac6c0).
[Jul 18 15:15:05] DEBUG[4315]: app_queue.c:2379 try_calling: SIP/ss1tampa.mixnetworks.com-084ac6c0 is trying to call a queue member.
[Jul 18 15:15:05] DEBUG[4315]: app_queue.c:1738 ring_one: Trying 'SIP/u301#xfertest' with metric 0
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3856)
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3893 sip_new: This channel will not be able to handle video.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-11.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-10.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-9.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-8.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-5.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-4.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q_RES.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-5.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-4.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_CHECK.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-13.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-12.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-11.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-10.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-9.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable MY_QUEUE.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-8.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~description~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~name~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-7.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-6.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-5.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ACTION.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-4.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_ID.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable FORWARD_CONTEXT.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-16.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-15.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-14.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-13.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-12.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-11.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-10.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CMD.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-9.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-8.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-7.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_pbx~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_dest_address_id~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_destination~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_source~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-6.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-5.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-7.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-6.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable BLOCK_POOL.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-5.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MAXCALLS.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CALLGROUP.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-4.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable PBX.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DID.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-5.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-4.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DATA.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable TYPE.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-4.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-3.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-2.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-14166287392-1.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jul 18 15:15:05] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2882 sip_call: Outgoing Call for u301#xfertest
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:2897 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:15:05] DEBUG[4315]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jul 18 15:15:05] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '594127a71ddc6f37566f8c7c2631dd29@8.7.177.15' Request 102: Found
[Jul 18 15:15:05] DEBUG[4315]: res_musiconhold.c:254 ast_moh_files_next: SIP/ss1tampa.mixnetworks.com-084ac6c0 Opened file 1 '/var/lib/asterisk/sounds/moh/ast_standard/fpm-world-mix'
[Jul 18 15:15:05] DEBUG[4315]: rtp.c:2727 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jul 18 15:15:05] DEBUG[4315]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jul 18 15:15:05] DEBUG[4315]: channel.c:2147 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jul 18 15:15:05] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:05] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '594127a71ddc6f37566f8c7c2631dd29@8.7.177.15' Request 102: Found
[Jul 18 15:15:05] DEBUG[4307]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u301#xfertest-084c19c8
[Jul 18 15:15:05] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest
    -- SIP/u301#xfertest-084c19c8 is ringing
[Jul 18 15:15:05] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:15:05] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u301#xfertest - state 1 (Not in use)
[Jul 18 15:15:05] DEBUG[4317]: app_queue.c:553 changethread: Device 'SIP/u301#xfertest' changed to state '1' (Not in use)
[Jul 18 15:15:07] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:10] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
    -- Nobody picked up in 10000 ms
[Jul 18 15:15:15] DEBUG[4315]: app_queue.c:1755 store_next: Next is 'SIP/u302#xfertest' with metric 1
[Jul 18 15:15:15] DEBUG[4315]: app_queue.c:2440 try_calling: SIP/ss1tampa.mixnetworks.com-084ac6c0: Nobody answered.
[Jul 18 15:15:15] DEBUG[4315]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/u301#xfertest-084c19c8'
[Jul 18 15:15:15] DEBUG[4315]: chan_sip.c:3368 sip_hangup: Hangup call SIP/u301#xfertest-084c19c8, SIP callid 594127a71ddc6f37566f8c7c2631dd29@8.7.177.15)
[Jul 18 15:15:15] DEBUG[4315]: chan_sip.c:2120 __sip_ack: Acked pending invite 102
[Jul 18 15:15:15] DEBUG[4315]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '594127a71ddc6f37566f8c7c2631dd29@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:15:15] DEBUG[4315]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u301#xfertest-084c19c8
[Jul 18 15:15:15] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest
[Jul 18 15:15:15] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '594127a71ddc6f37566f8c7c2631dd29@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:15:15] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:15:15] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u301#xfertest - state 1 (Not in use)
[Jul 18 15:15:15] DEBUG[4318]: app_queue.c:553 changethread: Device 'SIP/u301#xfertest' changed to state '1' (Not in use)
[Jul 18 15:15:15] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '594127a71ddc6f37566f8c7c2631dd29@8.7.177.15' of Request 102: Match Found
[Jul 18 15:15:15] DEBUG[4307]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:15:15] DEBUG[4307]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 594127a71ddc6f37566f8c7c2631dd29@8.7.177.15
Really destroying SIP dialog '594127a71ddc6f37566f8c7c2631dd29@8.7.177.15' Method: INVITE
[Jul 18 15:15:17] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:20] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:20] DEBUG[4315]: app_queue.c:2116 is_our_turn: It's our turn (SIP/ss1tampa.mixnetworks.com-084ac6c0).
    -- Stopped music on hold on SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:20] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:20] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'queue-youarenext' (language 'en')
[Jul 18 15:15:22] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:25] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 90 sample intervals
[Jul 18 15:15:25] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:25] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
    -- Told SIP/ss1tampa.mixnetworks.com-084ac6c0 in xfertest_CQ_39 their queue position (which was 1)
[Jul 18 15:15:25] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'queue-thankyou' (language 'en')
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 119 sample intervals
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2727 ast_prod: Prodding channel 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
    -- Started music on hold, class 'default', on SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
[Jul 18 15:15:27] DEBUG[4315]: app_queue.c:2379 try_calling: SIP/ss1tampa.mixnetworks.com-084ac6c0 is trying to call a queue member.
[Jul 18 15:15:27] DEBUG[4315]: app_queue.c:1738 ring_one: Trying 'SIP/u302#xfertest' with metric 1
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3856)
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3893 sip_new: This channel will not be able to handle video.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-11.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-10.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-9.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-8.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-5.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-4.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q_RES.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-5.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-4.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_CHECK.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-13.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-12.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-11.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-10.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-9.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable MY_QUEUE.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-8.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~description~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~name~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-7.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-6.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-5.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ACTION.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-4.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_ID.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable FORWARD_CONTEXT.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-16.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-15.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-14.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-13.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-12.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-11.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-10.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CMD.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-9.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-8.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-7.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_pbx~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_dest_address_id~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_destination~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_source~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-6.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-5.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-7.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-6.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable BLOCK_POOL.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-5.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MAXCALLS.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CALLGROUP.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-4.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable PBX.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DID.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-5.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-4.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DATA.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable TYPE.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-4.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-3.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-2.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-14166287392-1.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jul 18 15:15:27] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:2882 sip_call: Outgoing Call for u302#xfertest
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:2897 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:15:27] DEBUG[4315]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jul 18 15:15:27] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15' Request 102: Found
[Jul 18 15:15:27] DEBUG[4315]: res_musiconhold.c:254 ast_moh_files_next: SIP/ss1tampa.mixnetworks.com-084ac6c0 Opened file 1 '/var/lib/asterisk/sounds/moh/ast_standard/fpm-world-mix'
[Jul 18 15:15:27] DEBUG[4315]: rtp.c:2597 ast_rtp_raw_write: Difference is 920, ms is 135
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2147 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jul 18 15:15:27] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:27] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15' Request 102: Found
[Jul 18 15:15:27] DEBUG[4307]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u302#xfertest-084c19c8
    -- SIP/u302#xfertest-084c19c8 is ringing
[Jul 18 15:15:27] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u302#xfertest
[Jul 18 15:15:27] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest
[Jul 18 15:15:27] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u302#xfertest - state 1 (Not in use)
[Jul 18 15:15:27] DEBUG[4319]: app_queue.c:553 changethread: Device 'SIP/u302#xfertest' changed to state '1' (Not in use)
[Jul 18 15:15:30] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:35] DEBUG[4307]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for 5c6b0846150366485891c4b0756be080@8.7.177.99 - OPTIONS (No RTP)
[Jul 18 15:15:35] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
    -- Nobody picked up in 10000 ms
[Jul 18 15:15:37] DEBUG[4315]: app_queue.c:1755 store_next: Next is 'SIP/u303#xfertest' with metric 2
[Jul 18 15:15:37] DEBUG[4315]: app_queue.c:2440 try_calling: SIP/ss1tampa.mixnetworks.com-084ac6c0: Nobody answered.
[Jul 18 15:15:37] DEBUG[4315]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/u302#xfertest-084c19c8'
[Jul 18 15:15:37] DEBUG[4315]: chan_sip.c:3368 sip_hangup: Hangup call SIP/u302#xfertest-084c19c8, SIP callid 5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15)
[Jul 18 15:15:37] DEBUG[4315]: chan_sip.c:2120 __sip_ack: Acked pending invite 102
[Jul 18 15:15:37] DEBUG[4315]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:15:37] DEBUG[4315]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u302#xfertest-084c19c8
[Jul 18 15:15:37] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u302#xfertest
[Jul 18 15:15:37] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:15:37] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15' of Request 102: Match Found
[Jul 18 15:15:37] DEBUG[4307]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:15:37] DEBUG[4307]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15
Really destroying SIP dialog '5945ccd4701bcb913b39a5f436c1fd13@8.7.177.15' Method: INVITE
[Jul 18 15:15:37] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest
[Jul 18 15:15:37] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u302#xfertest - state 1 (Not in use)
[Jul 18 15:15:37] DEBUG[4320]: app_queue.c:553 changethread: Device 'SIP/u302#xfertest' changed to state '1' (Not in use)
[Jul 18 15:15:38] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:41] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:42] DEBUG[4315]: app_queue.c:2116 is_our_turn: It's our turn (SIP/ss1tampa.mixnetworks.com-084ac6c0).
[Jul 18 15:15:42] DEBUG[4315]: app_queue.c:2379 try_calling: SIP/ss1tampa.mixnetworks.com-084ac6c0 is trying to call a queue member.
[Jul 18 15:15:42] DEBUG[4315]: app_queue.c:1738 ring_one: Trying 'SIP/u303#xfertest' with metric 2
[Jul 18 15:15:42] DEBUG[4315]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jul 18 15:15:42] DEBUG[4315]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3856)
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u303#xfertest
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3893 sip_new: This channel will not be able to handle video.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-11.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-10.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-9.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-8.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-5.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-4.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q_RES.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-5.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-4.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_CHECK.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-13.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-12.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-11.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-10.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-9.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable MY_QUEUE.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-8.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~description~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~name~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-7.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-6.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-5.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ACTION.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-4.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_ID.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable FORWARD_CONTEXT.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-16.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-15.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-14.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-13.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-12.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-11.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-10.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CMD.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-9.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-8.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-7.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_pbx~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_dest_address_id~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_destination~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_source~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-6.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-5.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-7.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-6.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable BLOCK_POOL.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-5.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MAXCALLS.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CALLGROUP.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-4.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable PBX.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DID.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-5.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-4.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DATA.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable TYPE.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-4.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-3.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-2.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-14166287392-1.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jul 18 15:15:43] DEBUG[4315]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:2882 sip_call: Outgoing Call for u303#xfertest
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:2897 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:15:43] DEBUG[4315]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jul 18 15:15:43] DEBUG[4315]: rtp.c:2597 ast_rtp_raw_write: Difference is 848, ms is 126
[Jul 18 15:15:43] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15' Request 102: Found
[Jul 18 15:15:48] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:50] DEBUG[4307]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 18 15:15:50] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '7018708816414e9924af45d52b960bd9@8.7.177.15' of Request 102: Match Not Found
Really destroying SIP dialog '7018708816414e9924af45d52b960bd9@8.7.177.15' Method: OPTIONS
    -- Nobody picked up in 10000 ms
[Jul 18 15:15:53] DEBUG[4315]: app_queue.c:1755 store_next: Next is 'SIP/u301#xfertest' with metric 1000
[Jul 18 15:15:53] DEBUG[4315]: app_queue.c:2440 try_calling: SIP/ss1tampa.mixnetworks.com-084ac6c0: Nobody answered.
[Jul 18 15:15:53] DEBUG[4315]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/u303#xfertest-084c19c8'
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:3368 sip_hangup: Hangup call SIP/u303#xfertest-084c19c8, SIP callid 36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15)
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:2120 __sip_ack: Acked pending invite 102
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:15:53] DEBUG[4315]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u303#xfertest-084c19c8
[Jul 18 15:15:53] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u303#xfertest
[Jul 18 15:15:53] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15' of Request 102: Match Found
[Jul 18 15:15:53] DEBUG[4307]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:15:53] DEBUG[4307]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15
[Jul 18 15:15:53] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15' of Request 102: Match Not Found
Really destroying SIP dialog '36d740621cb1d3ee0e4e6a0a5c5e5953@8.7.177.15' Method: INVITE
[Jul 18 15:15:53] DEBUG[4315]: app_queue.c:3486 queue_exec: Timing out from 'n' option since we have rung 3 phones and there are 3 queue members
    -- Exiting on time-out cycle
    -- Stopped music on hold on SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:53] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:53] DEBUG[4315]: app_queue.c:1419 leave_queue: Queue 'xfertest_CQ_39' Leave, Channel 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose'
    -- Executing [new@sub-queues:12] Verbose("SIP/ss1tampa.mixnetworks.com-084ac6c0", "1|Queue is FULL or we returned from Queue") in new stack
 Queue is FULL or we returned from Queue
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Gosub'
    -- Executing [new@sub-queues:13] Gosub("SIP/ss1tampa.mixnetworks.com-084ac6c0", "sub-no_answer|s|1(QUEUE|7)") in new stack
[Jul 18 15:15:53] DEBUG[4315]: app_stack.c:174 gosub_exec: Setting 'ARG1' to 'QUEUE'
[Jul 18 15:15:53] DEBUG[4315]: app_stack.c:174 gosub_exec: Setting 'ARG2' to '7'
[Jul 18 15:15:53] DEBUG[4315]: app_stack.c:179 gosub_exec: Setting gosub return address to '2:sub-queues|new|14'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-no_answer:1] NoOp("SIP/ss1tampa.mixnetworks.com-084ac6c0", "") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-no_answer:2] Set("SIP/ss1tampa.mixnetworks.com-084ac6c0", "APP=QUEUE") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-no_answer:3] Set("SIP/ss1tampa.mixnetworks.com-084ac6c0", "ID=7") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NoOp()'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Exec'
    -- Executing [s@sub-no_answer:4] Exec("SIP/ss1tampa.mixnetworks.com-084ac6c0", "NoOp()") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VM,162,,xfertest'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-no_answer:5] Set("SIP/ss1tampa.mixnetworks.com-084ac6c0", "HASH(NOANS_DEST)=VM,162,,xfertest") in new stack
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:170 array: array (no_answer_destination,no_answer_destination_id,no_answer_destination_did,pbx=VM,162,,xfertest)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (no_answer_destination=VM)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (no_answer_destination_id=162)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (no_answer_destination_did=)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (pbx=xfertest)
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-no_answer:6] NoOp("SIP/ss1tampa.mixnetworks.com-084ac6c0", "") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:7] GotoIf("SIP/ss1tampa.mixnetworks.com-084ac6c0", "1?no_answer_handler") in new stack
    -- Goto (sub-no_answer,s,14)
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-no_answer:14] NoOp("SIP/ss1tampa.mixnetworks.com-084ac6c0", "") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'pbx,no_answer_destination_did,no_answer_destination_id,no_answer_destination'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:15] GotoIf("SIP/ss1tampa.mixnetworks.com-084ac6c0", "0?no_dest|1") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VM'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:16] GotoIf("SIP/ss1tampa.mixnetworks.com-084ac6c0", "0?aa|1") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VM'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:17] GotoIf("SIP/ss1tampa.mixnetworks.com-084ac6c0", "1?vm|1") in new stack
    -- Goto (sub-no_answer,vm,1)
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [vm@sub-no_answer:1] NoOp("SIP/ss1tampa.mixnetworks.com-084ac6c0", "") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '162'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '301,u301,xfertest'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [vm@sub-no_answer:2] Set("SIP/ss1tampa.mixnetworks.com-084ac6c0", "HASH(voicemail)=301,u301,xfertest") in new stack
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:170 array: array (pbx_extension,user_name,pbx=301,u301,xfertest)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (pbx_extension=301)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (user_name=u301)
[Jul 18 15:15:53] DEBUG[4315]: func_odbc.c:182 array: array set value (pbx=xfertest)
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'pbx,user_name,pbx_extension'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [vm@sub-no_answer:3] GotoIf("SIP/ss1tampa.mixnetworks.com-084ac6c0", "0no_dest|1") in new stack
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch
[Jul 18 15:15:53] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'Playback'
    -- Executing [vm@sub-no_answer:4] Playback("SIP/ss1tampa.mixnetworks.com-084ac6c0", "silence/1") in new stack
[Jul 18 15:15:53] DEBUG[4315]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:3525 sip_answer: SIP answering channel: SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:6499 transmit_response_with_sdp: Setting framing from config on incoming call
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:15:53] DEBUG[4315]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jul 18 15:15:53] DEBUG[4315]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jul 18 15:15:53] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'silence/1' (language 'en')
[Jul 18 15:15:53] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '2a9f7b52a78051a4-2a97-469e65e4-bd6e@8.7.177.101' of Response 1184785893: Match Not Found
[Jul 18 15:15:53] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u303#xfertest
[Jul 18 15:15:53] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u303#xfertest - state 1 (Not in use)
[Jul 18 15:15:53] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer ss1tampa.mixnetworks.com
[Jul 18 15:15:53] DEBUG[4321]: app_queue.c:553 changethread: Device 'SIP/u303#xfertest' changed to state '1' (Not in use)
[Jul 18 15:15:53] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/ss1tampa.mixnetworks.com - state 4 (Invalid)
[Jul 18 15:15:53] DEBUG[4322]: app_queue.c:547 changethread: Device 'SIP/ss1tampa.mixnetworks.com' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul 18 15:15:54] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:54] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:54] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '301'
[Jul 18 15:15:54] DEBUG[4315]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'xfertest'
[Jul 18 15:15:54] DEBUG[4315]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMail'
    -- Executing [vm@sub-no_answer:5] VoiceMail("SIP/ss1tampa.mixnetworks.com-084ac6c0", "301@xfertest|u") in new stack
[Jul 18 15:15:54] DEBUG[4315]: app_voicemail.c:2851 leave_voicemail: Before find_user
[Jul 18 15:15:54] DEBUG[4315]: app_voicemail.c:2919 leave_voicemail: /var/spool/asterisk/voicemail/xfertest/301/unavail doesn't exist, doing what we can
[Jul 18 15:15:54] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'vm-theperson' (language 'en')
[Jul 18 15:15:55] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 73 sample intervals
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'digits/3' (language 'en')
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 157 sample intervals
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:56] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'digits/0' (language 'en')
[Jul 18 15:15:57] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 144 sample intervals
[Jul 18 15:15:57] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:57] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:57] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'digits/1' (language 'en')
[Jul 18 15:15:57] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:15:58] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 36 sample intervals
[Jul 18 15:15:58] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:58] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:58] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'vm-isunavail' (language 'en')
[Jul 18 15:15:59] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 127 sample intervals
[Jul 18 15:15:59] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:59] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:59] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084ac6c0> Playing 'vm-intro' (language 'en')
[Jul 18 15:15:59] DEBUG[4315]: rtp.c:875 ast_rtcp_read: Got RTCP report of 72 bytes
[Jul 18 15:15:59] DEBUG[4307]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2a9f7b52a78051a4-2a97-469e65e4-bd6e@8.7.177.101
[Jul 18 15:15:59] DEBUG[4307]: chan_sip.c:14398 handle_request_bye: Received bye, issuing owner hangup
[Jul 18 15:15:59] DEBUG[4315]: pbx.c:2407 __ast_pbx_run: Spawn extension (sub-no_answer,vm,5) exited non-zero on 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
  == Spawn extension (sub-no_answer, vm, 5) exited non-zero on 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
[Jul 18 15:15:59] DEBUG[4315]: channel.c:1539 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
[Jul 18 15:15:59] DEBUG[4315]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:15:59] DEBUG[4315]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/ss1tampa.mixnetworks.com-084ac6c0'
[Jul 18 15:15:59] DEBUG[4315]: chan_sip.c:3368 sip_hangup: Hangup call SIP/ss1tampa.mixnetworks.com-084ac6c0, SIP callid 2a9f7b52a78051a4-2a97-469e65e4-bd6e@8.7.177.101)
[Jul 18 15:15:59] DEBUG[4315]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/ss1tampa.mixnetworks.com-084ac6c0
[Jul 18 15:15:59] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer ss1tampa.mixnetworks.com
[Jul 18 15:15:59] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/ss1tampa.mixnetworks.com - state 4 (Invalid)
[Jul 18 15:15:59] DEBUG[4323]: app_queue.c:547 changethread: Device 'SIP/ss1tampa.mixnetworks.com' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
Really destroying SIP dialog '2a9f7b52a78051a4-2a97-469e65e4-bd6e@8.7.177.101' Method: BYE
[Jul 18 15:16:07] DEBUG[4307]: chan_sip.c:2059 __sip_autodestruct: Auto destroying SIP dialog '5c6b0846150366485891c4b0756be080@8.7.177.99'
[Jul 18 15:16:07] DEBUG[4307]: chan_sip.c:3165 sip_destroy: Destroying SIP dialog 5c6b0846150366485891c4b0756be080@8.7.177.99
Really destroying SIP dialog '5c6b0846150366485891c4b0756be080@8.7.177.99' Method: OPTIONS



END OF CALL 1


START OF CALL 2



[Jul 18 15:16:15] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Queue'
    -- Executing [new@sub-queues:11] Queue("SIP/ss1tampa.mixnetworks.com-084be988", "xfertest_CQ_39|n") in new stack
[Jul 18 15:16:15] DEBUG[4324]: app_queue.c:3362 queue_exec: NO QUEUE_PRIO variable found. Using default.
[Jul 18 15:16:15] DEBUG[4324]: app_queue.c:3385 queue_exec: queue: xfertest_CQ_39, options: n, url: (null), announce: (null), expires: 0, priority: 0
[Jul 18 15:16:15] DEBUG[4324]: app_queue.c:1225 join_queue: Queue 'xfertest_CQ_39' Join, Channel 'SIP/ss1tampa.mixnetworks.com-084be988', Position '1'
[Jul 18 15:16:15] DEBUG[4324]: channel.c:2727 ast_prod: Prodding channel 'SIP/ss1tampa.mixnetworks.com-084be988'
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6499 transmit_response_with_sdp: Setting framing from config on incoming call
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
    -- Started music on hold, class 'default', on SIP/ss1tampa.mixnetworks.com-084be988
[Jul 18 15:16:15] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
[Jul 18 15:16:15] DEBUG[4324]: app_queue.c:2116 is_our_turn: It's our turn (SIP/ss1tampa.mixnetworks.com-084be988).
[Jul 18 15:16:15] DEBUG[4324]: app_queue.c:2379 try_calling: SIP/ss1tampa.mixnetworks.com-084be988 is trying to call a queue member.
[Jul 18 15:16:15] DEBUG[4324]: app_queue.c:1738 ring_one: Trying 'SIP/u301#xfertest' with metric 0
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 18 15:16:15] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/ss1tampa.mixnetworks.com - state 4 (Invalid)
[Jul 18 15:16:15] DEBUG[4325]: app_queue.c:547 changethread: Device 'SIP/ss1tampa.mixnetworks.com' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3856)
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3893 sip_new: This channel will not be able to handle video.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-11.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-10.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-9.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-new-8.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-5.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-4.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable REMOTE_Q_RES.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-find-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-5.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-4.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_CHECK.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-conn-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-13.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-12.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-11.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-10.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-9.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable MY_QUEUE.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-8.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~description~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~queue~name~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-7.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-6.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-5.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ACTION.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-4.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable Q_ID.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3465 ast_channel_inherit_variables: Copying hard-transferable variable FORWARD_CONTEXT.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-queues-4166287392-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-qq-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-16.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-15.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-14.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-13.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-12.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-11.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-10.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CMD.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-9.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-8.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-7.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_pbx~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_dest_address_id~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_destination~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~HASH~ROUTE_ROUTE~did_source~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-6.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-5.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-return-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-chk-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-7.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-6.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable BLOCK_POOL.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-5.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MAXCALLS.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable CALLGROUP.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-4.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable PBX.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DID.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-did-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-5.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-4.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable DATA.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable TYPE.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-callgroups-s-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-4.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-3.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-sub-route-s-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-2.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-4166287392-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-from-voip-14166287392-1.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jul 18 15:16:15] DEBUG[4324]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:2882 sip_call: Outgoing Call for u301#xfertest
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:2897 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:16:15] DEBUG[4324]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jul 18 15:16:15] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '137a907c6be63c0740c39e0b212df1c3@8.7.177.15' Request 102: Found
[Jul 18 15:16:15] DEBUG[4324]: res_musiconhold.c:254 ast_moh_files_next: SIP/ss1tampa.mixnetworks.com-084be988 Opened file 1 '/var/lib/asterisk/sounds/moh/ast_standard/fpm-world-mix'
[Jul 18 15:16:15] DEBUG[4324]: rtp.c:2727 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jul 18 15:16:15] DEBUG[4324]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jul 18 15:16:15] DEBUG[4324]: channel.c:2147 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jul 18 15:16:15] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:15] DEBUG[4307]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '137a907c6be63c0740c39e0b212df1c3@8.7.177.15' Request 102: Found
[Jul 18 15:16:15] DEBUG[4307]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u301#xfertest-084c11d8
[Jul 18 15:16:15] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest
    -- SIP/u301#xfertest-084c11d8 is ringing
[Jul 18 15:16:15] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:16:15] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u301#xfertest - state 1 (Not in use)
[Jul 18 15:16:15] DEBUG[4326]: app_queue.c:553 changethread: Device 'SIP/u301#xfertest' changed to state '1' (Not in use)
[Jul 18 15:16:17] DEBUG[4324]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:16:18] DEBUG[4324]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
[Jul 18 15:16:25] DEBUG[4324]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes
    -- Nobody picked up in 10000 ms
[Jul 18 15:16:25] DEBUG[4324]: app_queue.c:1755 store_next: Next is 'SIP/u302#xfertest' with metric 1
[Jul 18 15:16:25] DEBUG[4324]: app_queue.c:2440 try_calling: SIP/ss1tampa.mixnetworks.com-084be988: Nobody answered.
[Jul 18 15:16:25] DEBUG[4324]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/u301#xfertest-084c11d8'
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:3368 sip_hangup: Hangup call SIP/u301#xfertest-084c11d8, SIP callid 137a907c6be63c0740c39e0b212df1c3@8.7.177.15)
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:2120 __sip_ack: Acked pending invite 102
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '137a907c6be63c0740c39e0b212df1c3@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:16:25] DEBUG[4324]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u301#xfertest-084c11d8
[Jul 18 15:16:25] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest
[Jul 18 15:16:25] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '137a907c6be63c0740c39e0b212df1c3@8.7.177.15' of Request 102: Match Not Found
[Jul 18 15:16:25] DEBUG[4324]: app_queue.c:3486 queue_exec: Timing out from 'n' option since we have rung 1 phones and there are 0 queue members
    -- Exiting on time-out cycle
    -- Stopped music on hold on SIP/ss1tampa.mixnetworks.com-084be988
[Jul 18 15:16:25] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:25] DEBUG[4324]: app_queue.c:1419 leave_queue: Queue 'xfertest_CQ_39' Leave, Channel 'SIP/ss1tampa.mixnetworks.com-084be988'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose'
    -- Executing [new@sub-queues:12] Verbose("SIP/ss1tampa.mixnetworks.com-084be988", "1|Queue is FULL or we returned from Queue") in new stack
 Queue is FULL or we returned from Queue
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Gosub'
    -- Executing [new@sub-queues:13] Gosub("SIP/ss1tampa.mixnetworks.com-084be988", "sub-no_answer|s|1(QUEUE|7)") in new stack
[Jul 18 15:16:25] DEBUG[4324]: app_stack.c:174 gosub_exec: Setting 'ARG1' to 'QUEUE'
[Jul 18 15:16:25] DEBUG[4324]: app_stack.c:174 gosub_exec: Setting 'ARG2' to '7'
[Jul 18 15:16:25] DEBUG[4324]: app_stack.c:179 gosub_exec: Setting gosub return address to '2:sub-queues|new|14'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-no_answer:1] NoOp("SIP/ss1tampa.mixnetworks.com-084be988", "") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-no_answer:2] Set("SIP/ss1tampa.mixnetworks.com-084be988", "APP=QUEUE") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-no_answer:3] Set("SIP/ss1tampa.mixnetworks.com-084be988", "ID=7") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NoOp()'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Exec'
    -- Executing [s@sub-no_answer:4] Exec("SIP/ss1tampa.mixnetworks.com-084be988", "NoOp()") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VM,162,,xfertest'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-no_answer:5] Set("SIP/ss1tampa.mixnetworks.com-084be988", "HASH(NOANS_DEST)=VM,162,,xfertest") in new stack
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:170 array: array (no_answer_destination,no_answer_destination_id,no_answer_destination_did,pbx=VM,162,,xfertest)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (no_answer_destination=VM)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (no_answer_destination_id=162)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (no_answer_destination_did=)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (pbx=xfertest)
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-no_answer:6] NoOp("SIP/ss1tampa.mixnetworks.com-084be988", "") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:7] GotoIf("SIP/ss1tampa.mixnetworks.com-084be988", "1?no_answer_handler") in new stack
    -- Goto (sub-no_answer,s,14)
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-no_answer:14] NoOp("SIP/ss1tampa.mixnetworks.com-084be988", "") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'pbx,no_answer_destination_did,no_answer_destination_id,no_answer_destination'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:15] GotoIf("SIP/ss1tampa.mixnetworks.com-084be988", "0?no_dest|1") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VM'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:16] GotoIf("SIP/ss1tampa.mixnetworks.com-084be988", "0?aa|1") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'VM'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-no_answer:17] GotoIf("SIP/ss1tampa.mixnetworks.com-084be988", "1?vm|1") in new stack
    -- Goto (sub-no_answer,vm,1)
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [vm@sub-no_answer:1] NoOp("SIP/ss1tampa.mixnetworks.com-084be988", "") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '162'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '301,u301,xfertest'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [vm@sub-no_answer:2] Set("SIP/ss1tampa.mixnetworks.com-084be988", "HASH(voicemail)=301,u301,xfertest") in new stack
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:170 array: array (pbx_extension,user_name,pbx=301,u301,xfertest)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (pbx_extension=301)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (user_name=u301)
[Jul 18 15:16:25] DEBUG[4324]: func_odbc.c:182 array: array set value (pbx=xfertest)
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'pbx,user_name,pbx_extension'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0'
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [vm@sub-no_answer:3] GotoIf("SIP/ss1tampa.mixnetworks.com-084be988", "0no_dest|1") in new stack
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch
[Jul 18 15:16:25] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'Playback'
    -- Executing [vm@sub-no_answer:4] Playback("SIP/ss1tampa.mixnetworks.com-084be988", "silence/1") in new stack
[Jul 18 15:16:25] DEBUG[4324]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/ss1tampa.mixnetworks.com-084be988
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:3525 sip_answer: SIP answering channel: SIP/ss1tampa.mixnetworks.com-084be988
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:6499 transmit_response_with_sdp: Setting framing from config on incoming call
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP
[Jul 18 15:16:25] DEBUG[4324]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jul 18 15:16:25] DEBUG[4324]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jul 18 15:16:25] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'silence/1' (language 'en')
[Jul 18 15:16:25] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '49903e03521a7daa-2abc-469e662b-d09d@8.7.177.101' of Response 1184785964: Match Not Found
[Jul 18 15:16:25] DEBUG[4292]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest
[Jul 18 15:16:25] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/u301#xfertest - state 1 (Not in use)
[Jul 18 15:16:25] DEBUG[4292]: chan_sip.c:15481 sip_devicestate: Checking device state for peer ss1tampa.mixnetworks.com
[Jul 18 15:16:25] DEBUG[4327]: app_queue.c:553 changethread: Device 'SIP/u301#xfertest' changed to state '1' (Not in use)
[Jul 18 15:16:25] DEBUG[4307]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '137a907c6be63c0740c39e0b212df1c3@8.7.177.15' of Request 102: Match Found
[Jul 18 15:16:25] DEBUG[4307]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call
[Jul 18 15:16:25] DEBUG[4307]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 137a907c6be63c0740c39e0b212df1c3@8.7.177.15
Really destroying SIP dialog '137a907c6be63c0740c39e0b212df1c3@8.7.177.15' Method: INVITE
[Jul 18 15:16:25] DEBUG[4292]: devicestate.c:287 do_state_change: Changing state for SIP/ss1tampa.mixnetworks.com - state 4 (Invalid)
[Jul 18 15:16:25] DEBUG[4328]: app_queue.c:547 changethread: Device 'SIP/ss1tampa.mixnetworks.com' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jul 18 15:16:26] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:26] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:26] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '301'
[Jul 18 15:16:26] DEBUG[4324]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'xfertest'
[Jul 18 15:16:26] DEBUG[4324]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMail'
    -- Executing [vm@sub-no_answer:5] VoiceMail("SIP/ss1tampa.mixnetworks.com-084be988", "301@xfertest|u") in new stack
[Jul 18 15:16:26] DEBUG[4324]: app_voicemail.c:2851 leave_voicemail: Before find_user
[Jul 18 15:16:26] DEBUG[4324]: app_voicemail.c:2919 leave_voicemail: /var/spool/asterisk/voicemail/xfertest/301/unavail doesn't exist, doing what we can
[Jul 18 15:16:26] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'vm-theperson' (language 'en')
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 73 sample intervals
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'digits/3' (language 'en')
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 157 sample intervals
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:28] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'digits/0' (language 'en')
[Jul 18 15:16:29] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 144 sample intervals
[Jul 18 15:16:29] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:29] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:29] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'digits/1' (language 'en')
[Jul 18 15:16:30] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 36 sample intervals
[Jul 18 15:16:30] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:30] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:30] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'vm-isunavail' (language 'en')
[Jul 18 15:16:31] DEBUG[4324]: rtp.c:875 ast_rtcp_read: Got RTCP report of 72 bytes
[Jul 18 15:16:31] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 127 sample intervals
[Jul 18 15:16:31] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:31] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals
[Jul 18 15:16:31] DEBUG[4324]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals
    -- <SIP/ss1tampa.mixnetworks.com-084be988> Playing 'vm-intro' (language 'en')
[Jul 18 15:16:35] DEBUG[4307]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for 001c262815eee4fb5aad9a2a58b8d901@8.7.177.99 - OPTIONS (No RTP)