Asterisk SVN-trunk-r41648M, Copyright (C) 1999 - 2006 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'show license' for details.
=========================================================================
Parsing /etc/asterisk/asterisk.conf
Parsing /etc/asterisk/extconfig.conf
Connected to Asterisk SVN-trunk-r41648M currently running on tampa99 (pid = 22648)
tampa99*CLI> Verbosity is at least 3
Core debug is at least 4
[Ktampa99*CLI> [Sep  2 14:00:04] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4143[0;37;40m [1;37;40msip_alloc[0;37;40m:  Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
 [Ktampa99*CLI> [Sep  2 14:00:04] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '6db2d9385305f2e97ca4b9a66759942d@8.7.177.99' of Request 102: Match Not Found
 Really destroying SIP dialog '6db2d9385305f2e97ca4b9a66759942d@8.7.177.99' Method: OPTIONS
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4143[0;37;40m [1;37;40msip_alloc[0;37;40m:  Allocating new SIP dialog for 7F9DC516-35AA-24D9-4C0A-47491EEB1A5A@192.168.1.101 - INVITE (With RTP)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14042[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received INVITE (5) - Command in SIP INVITE
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m8681[0;37;40m [1;37;40mcheck_user_full[0;37;40m:  Setting NAT on RTP to On
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m8691[0;37;40m [1;37;40mcheck_user_full[0;37;40m:  Setting NAT on UDPTL to On
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14042[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received ACK (6) - Command in SIP ACK
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '7F9DC516-35AA-24D9-4C0A-47491EEB1A5A@192.168.1.101' of Response 3819: Match Not Found
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14042[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received INVITE (5) - Command in SIP INVITE
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m8681[0;37;40m [1;37;40mcheck_user_full[0;37;40m:  Setting NAT on RTP to On
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m8691[0;37;40m [1;37;40mcheck_user_full[0;37;40m:  Setting NAT on UDPTL to On
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4868[0;37;40m [1;37;40mprocess_sdp[0;37;40m:  T38 state changed to 0 on channel <none>
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4938[0;37;40m [1;37;40mprocess_sdp[0;37;40m:  We're settling with these formats: 0xe (gsm|ulaw|alaw)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12854[0;37;40m [1;37;40mhandle_request_invite[0;37;40m:  Checking SIP call limits for device lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for incoming call
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mframe.c[0;37;40m:[1;37;40m1119[0;37;40m [1;37;40mast_codec_choose[0;37;40m:  Could not find preferred codec - Going for the best codec
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3638[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our native formats are 0x4 (ulaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3639[0;37;40m [1;37;40msip_new[0;37;40m:  *** Joint capabilities are 0xe (gsm|ulaw|alaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3640[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mframe.c[0;37;40m:[1;37;40m1119[0;37;40m [1;37;40mast_codec_choose[0;37;40m:  Could not find preferred codec - Going for the best codec
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3641[0;37;40m [1;37;40msip_new[0;37;40m:  *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3664[0;37;40m [1;37;40msip_new[0;37;40m:  This channel will not be able to handle video.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m7622[0;37;40m [1;37;40mbuild_route[0;37;40m:  build_route: Contact hop: <sip:lmadsen%23sokol@70.24.153.228:5060>
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12925[0;37;40m [1;37;40mhandle_request_invite[0;37;40m:  SIP/lmadsen#sokol-08cd8d00: New call is still down.... Trying... 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m:  Notification of state change to be queued on device/channel SIP/lmadsen#sokol-08cd8d00
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for SIP/lmadsen#sokol - state 1 (Not in use)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1683[0;37;40m [1;37;40mpbx_extension_helper[0;37;40m:  Launching 'Verbose'
     -- Executing [*4868@sokol_longdistance:1] [1;36;40mVerbose[0;37;40m("[1;35;40mSIP/lmadsen#sokol-08cd8d00[0;37;40m", "[1;35;40m1|Huntgroup Test #1[0;37;40m") in new stack
  Huntgroup Test #1
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1683[0;37;40m [1;37;40mpbx_extension_helper[0;37;40m:  Launching 'Queue'
     -- Executing [*4868@sokol_longdistance:2] [1;36;40mQueue[0;37;40m("[1;35;40mSIP/lmadsen#sokol-08cd8d00[0;37;40m", "[1;35;40mtestq|n[0;37;40m") in new stack
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m3275[0;37;40m [1;37;40mqueue_exec[0;37;40m:  NO QUEUE_PRIO variable found. Using default.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m3298[0;37;40m [1;37;40mqueue_exec[0;37;40m:  queue: testq, options: n, url: (null), announce: (null), expires: 0, priority: 0
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1190[0;37;40m [1;37;40mjoin_queue[0;37;40m:  Queue 'testq' Join, Channel 'SIP/lmadsen#sokol-08cd8d00', Position '1'
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2379[0;37;40m [1;37;40mast_prod[0;37;40m:  Prodding channel 'SIP/lmadsen#sokol-08cd8d00'
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5838[0;37;40m [1;37;40madd_sdp[0;37;40m:  ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5839[0;37;40m [1;37;40madd_sdp[0;37;40m:  ** Our prefcodec: 0x0 (nothing) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5991[0;37;40m [1;37;40madd_sdp[0;37;40m:  -- Done with adding codecs to SDP
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m6030[0;37;40m [1;37;40madd_sdp[0;37;40m:  Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
     -- Started music on hold, class 'default', on SIP/lmadsen#sokol-08cd8d00
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2068[0;37;40m [1;37;40mis_our_turn[0;37;40m:  It's our turn (SIP/lmadsen#sokol-08cd8d00).
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2325[0;37;40m [1;37;40mtry_calling[0;37;40m:  SIP/lmadsen#sokol-08cd8d00 is trying to call a queue member.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1701[0;37;40m [1;37;40mring_one[0;37;40m:  Trying 'SIP/lmadsen#sokol' with metric 1000
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14687[0;37;40m [1;37;40msip_request_call[0;37;40m:  Asked to create a SIP channel with formats: 0x4 (ulaw)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4143[0;37;40m [1;37;40msip_alloc[0;37;40m:  Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2508[0;37;40m [1;37;40mcreate_addr_from_peer[0;37;40m:  Our T38 capability (3856)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2518[0;37;40m [1;37;40mcreate_addr_from_peer[0;37;40m:  Setting NAT on RTP to On
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2532[0;37;40m [1;37;40mcreate_addr_from_peer[0;37;40m:  Setting NAT on UDPTL to On
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mframe.c[0;37;40m:[1;37;40m1119[0;37;40m [1;37;40mast_codec_choose[0;37;40m:  Could not find preferred codec - Going for the best codec
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3638[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our native formats are 0x4 (ulaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3639[0;37;40m [1;37;40msip_new[0;37;40m:  *** Joint capabilities are 0x0 (nothing) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3640[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mframe.c[0;37;40m:[1;37;40m1119[0;37;40m [1;37;40mast_codec_choose[0;37;40m:  Could not find preferred codec - Going for the best codec
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3641[0;37;40m [1;37;40msip_new[0;37;40m:  *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3643[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3664[0;37;40m [1;37;40msip_new[0;37;40m:  This channel will not be able to handle video.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-sokol_longdistance-*4868-2.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-sokol_longdistance-*4868-1.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable ANI.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable PEERNAME.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable REWRITECIDNUM.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable RESTRICTCID.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPCALLID.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPUSERAGENT.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPDOMAIN.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPURI.
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2718[0;37;40m [1;37;40msip_call[0;37;40m:  Outgoing Call for lmadsen%23sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for outgoing call
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23sokol is not a local device, no call limit
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2726[0;37;40m [1;37;40msip_call[0;37;40m:  Our T38 capability (3856), joint T38 capability (3856)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5838[0;37;40m [1;37;40madd_sdp[0;37;40m:  ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5839[0;37;40m [1;37;40madd_sdp[0;37;40m:  ** Our prefcodec: 0x4 (ulaw) 
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5854[0;37;40m [1;37;40madd_sdp[0;37;40m:  This call needs video offers, but there's no video support enabled ! 
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5991[0;37;40m [1;37;40madd_sdp[0;37;40m:  -- Done with adding codecs to SDP
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m6030[0;37;40m [1;37;40madd_sdp[0;37;40m:  Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263)
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4848]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m539[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3923[0;37;40m [1;37;40msip_rtp_read[0;37;40m:  Oooh, format changed to 2
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2604[0;37;40m [1;37;40mset_format[0;37;40m:  Set channel SIP/lmadsen#sokol-08cd8d00 to read format ulaw
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2604[0;37;40m [1;37;40mset_format[0;37;40m:  Set channel SIP/lmadsen#sokol-08cd8d00 to write format ulaw
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2137[0;37;40m [1;37;40m__ast_read[0;37;40m:  Auto-deactivating generator
     -- Stopped music on hold on SIP/lmadsen#sokol-08cd8d00
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2054[0;37;40m [1;37;40m__sip_semi_ack[0;37;40m:  (Provisional) Stopping retransmission (but retaining packet) on '7f44aca77e968e63520dd00a731f6ccf@8.7.177.99' Request 102: Found
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11210[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 100 to standard invite
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2054[0;37;40m [1;37;40m__sip_semi_ack[0;37;40m:  (Provisional) Stopping retransmission (but retaining packet) on '7f44aca77e968e63520dd00a731f6ccf@8.7.177.99' Request 102: Found
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11210[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 180 to standard invite
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m:  Notification of state change to be queued on device/channel SIP/lmadsen#sokol-08d16408
 [Ktampa99*CLI>     -- SIP/lmadsen#sokol-08d16408 is ringing
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for SIP/lmadsen#sokol - state 1 (Not in use)
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Ktampa99*CLI> [Sep  2 14:00:10] [1;32;40mDEBUG[0;37;40m[4849]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m539[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI>     -- Nobody picked up in 6000 ms
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2386[0;37;40m [1;37;40mtry_calling[0;37;40m:  SIP/lmadsen#sokol-08cd8d00: Nobody answered.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1511[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lmadsen#sokol-08d16408'
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3180[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hangup call SIP/lmadsen#sokol-08d16408, SIP callid 7f44aca77e968e63520dd00a731f6ccf@8.7.177.99)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for outgoing call
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23sokol is not a local device, no call limit
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3201[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hanging up channel in state Ringing (not UP)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1994[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Acked pending invite 102
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '7f44aca77e968e63520dd00a731f6ccf@8.7.177.99' of Request 102: Match Not Found
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m:  Notification of state change to be queued on device/channel SIP/lmadsen#sokol-08d16408
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2068[0;37;40m [1;37;40mis_our_turn[0;37;40m:  It's our turn (SIP/lmadsen#sokol-08cd8d00).
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2325[0;37;40m [1;37;40mtry_calling[0;37;40m:  SIP/lmadsen#sokol-08cd8d00 is trying to call a queue member.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1701[0;37;40m [1;37;40mring_one[0;37;40m:  Trying 'SIP/lmadsen#sokol' with metric 1000
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14687[0;37;40m [1;37;40msip_request_call[0;37;40m:  Asked to create a SIP channel with formats: 0x2 (gsm)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4143[0;37;40m [1;37;40msip_alloc[0;37;40m:  Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2508[0;37;40m [1;37;40mcreate_addr_from_peer[0;37;40m:  Our T38 capability (3856)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2518[0;37;40m [1;37;40mcreate_addr_from_peer[0;37;40m:  Setting NAT on RTP to On
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2532[0;37;40m [1;37;40mcreate_addr_from_peer[0;37;40m:  Setting NAT on UDPTL to On
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mframe.c[0;37;40m:[1;37;40m1119[0;37;40m [1;37;40mast_codec_choose[0;37;40m:  Could not find preferred codec - Going for the best codec
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3638[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our native formats are 0x4 (ulaw) 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3639[0;37;40m [1;37;40msip_new[0;37;40m:  *** Joint capabilities are 0x0 (nothing) 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3640[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mframe.c[0;37;40m:[1;37;40m1119[0;37;40m [1;37;40mast_codec_choose[0;37;40m:  Could not find preferred codec - Going for the best codec
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3641[0;37;40m [1;37;40msip_new[0;37;40m:  *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3643[0;37;40m [1;37;40msip_new[0;37;40m:  *** Our preferred formats from the incoming channel are 0x2 (gsm) 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3664[0;37;40m [1;37;40msip_new[0;37;40m:  This channel will not be able to handle video.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-sokol_longdistance-*4868-2.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-sokol_longdistance-*4868-1.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable ANI.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable PEERNAME.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable REWRITECIDNUM.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable RESTRICTCID.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPCALLID.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPUSERAGENT.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPDOMAIN.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3069[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPURI.
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2718[0;37;40m [1;37;40msip_call[0;37;40m:  Outgoing Call for lmadsen%23sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for outgoing call
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23sokol is not a local device, no call limit
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2726[0;37;40m [1;37;40msip_call[0;37;40m:  Our T38 capability (3856), joint T38 capability (3856)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5838[0;37;40m [1;37;40madd_sdp[0;37;40m:  ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5839[0;37;40m [1;37;40madd_sdp[0;37;40m:  ** Our prefcodec: 0x2 (gsm) 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5854[0;37;40m [1;37;40madd_sdp[0;37;40m:  This call needs video offers, but there's no video support enabled ! 
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m5991[0;37;40m [1;37;40madd_sdp[0;37;40m:  -- Done with adding codecs to SDP
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m6030[0;37;40m [1;37;40madd_sdp[0;37;40m:  Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for SIP/lmadsen#sokol - state 1 (Not in use)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Ktampa99*CLI> [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4850]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m539[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '7f44aca77e968e63520dd00a731f6ccf@8.7.177.99' of Request 102: Match Found
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for outgoing call
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23sokol is not a local device, no call limit
 [Ktampa99*CLI> [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '7f44aca77e968e63520dd00a731f6ccf@8.7.177.99' of Request 102: Match Not Found
 Really destroying SIP dialog '7f44aca77e968e63520dd00a731f6ccf@8.7.177.99' Method: INVITE
 [Ktampa99*CLI> [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2054[0;37;40m [1;37;40m__sip_semi_ack[0;37;40m:  (Provisional) Stopping retransmission (but retaining packet) on '1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99' Request 102: Found
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11210[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 100 to standard invite
 [Ktampa99*CLI> [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2054[0;37;40m [1;37;40m__sip_semi_ack[0;37;40m:  (Provisional) Stopping retransmission (but retaining packet) on '1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99' Request 102: Found
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11210[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 180 to standard invite
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m:  Notification of state change to be queued on device/channel SIP/lmadsen#sokol-08d1a2e8
     -- SIP/lmadsen#sokol-08d1a2e8 is ringing
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for SIP/lmadsen#sokol - state 1 (Not in use)
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Ktampa99*CLI> [Sep  2 14:00:16] [1;32;40mDEBUG[0;37;40m[4851]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m539[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI>     -- Nobody picked up in 6000 ms
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2386[0;37;40m [1;37;40mtry_calling[0;37;40m:  SIP/lmadsen#sokol-08cd8d00: Nobody answered.
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1511[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lmadsen#sokol-08d1a2e8'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3180[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hangup call SIP/lmadsen#sokol-08d1a2e8, SIP callid 1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99)
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for outgoing call
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23sokol is not a local device, no call limit
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3201[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hanging up channel in state Ringing (not UP)
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1994[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Acked pending invite 102
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99' of Request 102: Match Not Found
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m:  Notification of state change to be queued on device/channel SIP/lmadsen#sokol-08d1a2e8
     -- Exiting on time-out cycle
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1388[0;37;40m [1;37;40mleave_queue[0;37;40m:  Queue 'testq' Leave, Channel 'SIP/lmadsen#sokol-08cd8d00'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m2279[0;37;40m [1;37;40m__ast_pbx_run[0;37;40m:  Spawn extension (sokol_longdistance,*4868,3) exited non-zero on 'SIP/lmadsen#sokol-08cd8d00'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '"Leif Madsen" <lmadsen#sokol>'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'lmadsen#sokol'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '*4868'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'sokol_longdistance'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'SIP/lmadsen#sokol-08cd8d00'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'Queue'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'testq|n'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '2006-09-02 14:00:10'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '2006-09-02 14:00:22'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '12'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '0'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'NO ANSWER'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'DOCUMENTATION'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'lmadsen#sokol'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '1157220010.35'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1537[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1511[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lmadsen#sokol-08cd8d00'
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3180[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hangup call SIP/lmadsen#sokol-08cd8d00, SIP callid 7F9DC516-35AA-24D9-4C0A-47491EEB1A5A@192.168.1.101)
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for incoming call
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3201[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hanging up channel in state Ring (not UP)
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4847]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m:  Notification of state change to be queued on device/channel SIP/lmadsen#sokol-08cd8d00
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for SIP/lmadsen#sokol - state 1 (Not in use)
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for SIP/lmadsen#sokol - state 1 (Not in use)
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m:  No provider found, checking channel drivers for SIP - lmadsen#sokol
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4668]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14629[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Ktampa99*CLI> [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4852]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m539[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4853]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m539[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99' of Request 102: Match Found
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2879[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  Updating call counter for outgoing call
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23sokol is not a local device, no call limit
 [Ktampa99*CLI> [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99' of Request 102: Match Not Found
 Really destroying SIP dialog '1fab52407ae49f9f5f04d4cc33882cbc@8.7.177.99' Method: INVITE
 [Ktampa99*CLI> [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14042[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received ACK (6) - Command in SIP ACK
 [Sep  2 14:00:22] [1;32;40mDEBUG[0;37;40m[4687]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2012[0;37;40m [1;37;40m__sip_ack[0;37;40m:  Stopping retransmission on '7F9DC516-35AA-24D9-4C0A-47491EEB1A5A@192.168.1.101' of Response 3820: Match Not Found
 Really destroying SIP dialog '7F9DC516-35AA-24D9-4C0A-47491EEB1A5A@192.168.1.101' Method: ACK
 [Ktampa99*CLI> exit
Executing last minute cleanups
Asterisk ending (0).