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 4
Core debug is at least 4
[Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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 0F800478-859D-1136-994C-14164011A83C@192.168.1.101 - INVITE (With RTP)
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14046[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received INVITE (5) - Command in SIP INVITE
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14046[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received ACK (6) - Command in SIP ACK
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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 '0F800478-859D-1136-994C-14164011A83C@192.168.1.101' of Response 11320: Match Not Found
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14046[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received INVITE (5) - Command in SIP INVITE
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12858[0;37;40m [1;37;40mhandle_request_invite[0;37;40m:  Checking SIP call limits for device lmadsen#sokol
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12929[0;37;40m [1;37;40mhandle_request_invite[0;37;40m:  SIP/lmadsen#sokol-084ed580: New call is still down.... Trying... 
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6833]: [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-084ed580
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1684[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-084ed580[0;37;40m", "[1;35;40m1|Huntgroup Test #1[0;37;40m") in new stack
  Huntgroup Test #1
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1684[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-084ed580[0;37;40m", "[1;35;40mtestq|c[0;37;40m") in new stack
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m3284[0;37;40m [1;37;40mqueue_exec[0;37;40m:  NO QUEUE_PRIO variable found. Using default.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m3309[0;37;40m [1;37;40mqueue_exec[0;37;40m:  queue: testq, options: c, url: (null), announce: (null), expires: 0, priority: 0
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1191[0;37;40m [1;37;40mjoin_queue[0;37;40m:  Queue 'testq' Join, Channel 'SIP/lmadsen#sokol-084ed580', Position '1'
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2382[0;37;40m [1;37;40mast_prod[0;37;40m:  Prodding channel 'SIP/lmadsen#sokol-084ed580'
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [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-084ed580
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2075[0;37;40m [1;37;40mis_our_turn[0;37;40m:  It's our turn (SIP/lmadsen#sokol-084ed580).
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2333[0;37;40m [1;37;40mtry_calling[0;37;40m:  SIP/lmadsen#sokol-084ed580 is trying to call a queue member.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1707[0;37;40m [1;37;40mring_one[0;37;40m:  Trying 'Local/group1@q-groups' with metric 2
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [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 Local/group1@q-groups-d65d,2
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-sokol_longdistance-*4868-2.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-sokol_longdistance-*4868-1.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable ANI.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable PEERNAME.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable REWRITECIDNUM.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable RESTRICTCID.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPCALLID.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPUSERAGENT.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPDOMAIN.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable SIPURI.
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [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 Local - group1@q-groups
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_local.c[0;37;40m:[1;37;40m144[0;37;40m [1;37;40mlocal_devicestate[0;37;40m:  Checking if extension group1@q-groups exists (devicestate)
 [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for Local/group1@q-groups - state 2 (In use)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7028]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7030]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'Local/group1@q-groups' changed to state '2' (In use)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1684[0;37;40m [1;37;40mpbx_extension_helper[0;37;40m:  Launching 'Verbose'
 [Ktampa99*CLI>     -- Executing [group1@q-groups:1] [1;36;40mVerbose[0;37;40m("[1;35;40mLocal/group1@q-groups-d65d,2[0;37;40m", "[1;35;40m1|Calling queue group 1[0;37;40m") in new stack
 [Ktampa99*CLI>  Calling queue group 1
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1684[0;37;40m [1;37;40mpbx_extension_helper[0;37;40m:  Launching 'Dial'
 [Ktampa99*CLI>     -- Executing [group1@q-groups:2] [1;36;40mDial[0;37;40m("[1;35;40mLocal/group1@q-groups-d65d,2[0;37;40m", "[1;35;40mSIP/lholmes#telcel&SIP/lmadsen#sokol&SIP/lmadsen#telcel[0;37;40m") in new stack
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14691[0;37;40m [1;37;40msip_request_call[0;37;40m:  Asked to create a SIP channel with formats: 0x4 (ulaw)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mrtp.c[0;37;40m:[1;37;40m1476[0;37;40m [1;37;40mast_rtp_make_compatible[0;37;40m:  Channel 'Local/group1@q-groups-d65d,2' has no RTP, not doing anything
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-q-groups-group1-2.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-q-groups-group1-1.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2718[0;37;40m [1;37;40msip_call[0;37;40m:  Outgoing Call for lholmes%23telcel
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lholmes%23telcel is not a local device, no call limit
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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>     -- Called lholmes#telcel
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14691[0;37;40m [1;37;40msip_request_call[0;37;40m:  Asked to create a SIP channel with formats: 0x4 (ulaw)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mrtp.c[0;37;40m:[1;37;40m1476[0;37;40m [1;37;40mast_rtp_make_compatible[0;37;40m:  Channel 'Local/group1@q-groups-d65d,2' has no RTP, not doing anything
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-q-groups-group1-2.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-q-groups-group1-1.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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>     -- Called lmadsen#sokol
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14691[0;37;40m [1;37;40msip_request_call[0;37;40m:  Asked to create a SIP channel with formats: 0x4 (ulaw)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mrtp.c[0;37;40m:[1;37;40m1476[0;37;40m [1;37;40mast_rtp_make_compatible[0;37;40m:  Channel 'Local/group1@q-groups-d65d,2' has no RTP, not doing anything
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-q-groups-group1-2.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m3072[0;37;40m [1;37;40mast_channel_inherit_variables[0;37;40m:  Not copying variable STACK-q-groups-group1-1.
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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%23telcel
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23telcel is not a local device, no call limit
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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)
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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) 
 [Ktampa99*CLI> [Sep  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:25] [1;32;40mDEBUG[0;37;40m[7029]: [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>     -- Called lmadsen#telcel
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7027]: [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  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2607[0;37;40m [1;37;40mset_format[0;37;40m:  Set channel SIP/lmadsen#sokol-084ed580 to read format ulaw
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2607[0;37;40m [1;37;40mset_format[0;37;40m:  Set channel SIP/lmadsen#sokol-084ed580 to write format ulaw
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m2140[0;37;40m [1;37;40m__ast_read[0;37;40m:  Auto-deactivating generator
     -- Stopped music on hold on SIP/lmadsen#sokol-084ed580
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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 '528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99' Request 102: Found
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11214[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 100 to standard invite
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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 '528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99' Request 102: Found
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11214[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 180 to standard invite
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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/lholmes#telcel-084eeae0
 [Ktampa99*CLI>     -- SIP/lholmes#telcel-084eeae0 is ringing
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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 - lholmes#telcel
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lholmes#telcel
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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/lholmes#telcel - state 1 (Not in use)
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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 - lholmes#telcel
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lholmes#telcel
     -- Local/group1@q-groups-d65d,1 is ringing
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7031]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lholmes#telcel' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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 '57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99' Request 102: Found
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11214[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 100 to standard invite
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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 '57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99' Request 102: Found
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11214[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 180 to standard invite
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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-084d3040
 [Ktampa99*CLI>     -- SIP/lmadsen#sokol-084d3040 is ringing
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7032]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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 '3826bb2724c5ab0c074e2d4751186142@8.7.177.99' Request 102: Found
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m11214[0;37;40m [1;37;40mhandle_response_invite[0;37;40m:  SIP response 100 to standard invite
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6833]: [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 '3826bb2724c5ab0c074e2d4751186142@8.7.177.99' of Request 102: Match Not Found
     -- Got SIP response 486 "Busy" back from 70.24.153.228
 [Ktampa99*CLI>     -- SIP/lmadsen#telcel-084d6f20 is busy
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1512[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lmadsen#telcel-084d6f20'
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7029]: [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#telcel-084d6f20, SIP callid 3826bb2724c5ab0c074e2d4751186142@8.7.177.99)
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lmadsen%23telcel is not a local device, no call limit
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7029]: [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 Down (not UP)
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7029]: [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#telcel-084d6f20
 [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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#telcel
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#telcel
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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#telcel - state 1 (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [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#telcel
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#telcel
 [Ktampa99*CLI> [Sep  3 14:25:26] [1;32;40mDEBUG[0;37;40m[7033]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m534[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#telcel' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
 [Ktampa99*CLI> Really destroying SIP dialog '3826bb2724c5ab0c074e2d4751186142@8.7.177.99' Method: INVITE
 [Ktampa99*CLI>     -- Nobody picked up in 6000 ms
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1724[0;37;40m [1;37;40mstore_next[0;37;40m:  Next is 'SIP/lholmes#telcel' with metric 1000
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m2394[0;37;40m [1;37;40mtry_calling[0;37;40m:  SIP/lmadsen#sokol-084ed580: Nobody answered.
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1512[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'Local/group1@q-groups-d65d,1'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [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 Local/group1@q-groups-d65d,1
     -- Done with one cycle, time to exit.
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m1389[0;37;40m [1;37;40mleave_queue[0;37;40m:  Queue 'testq' Leave, Channel 'SIP/lmadsen#sokol-084ed580'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m2280[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-084ed580'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '"Leif Madsen" <lmadsen#sokol>'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'lmadsen#sokol'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '*4868'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'sokol_longdistance'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'SIP/lmadsen#sokol-084ed580'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'Queue'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'testq|c'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '2006-09-03 14:25:25'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '2006-09-03 14:25:32'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '7'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '0'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'NO ANSWER'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'DOCUMENTATION'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'lmadsen#sokol'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '1157307925.4'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1512[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lmadsen#sokol-084ed580'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [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-084ed580, SIP callid 0F800478-859D-1136-994C-14164011A83C@192.168.1.101)
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7027]: [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-084ed580
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mrtp.c[0;37;40m:[1;37;40m1400[0;37;40m [1;37;40mast_rtp_early_bridge[0;37;40m:  Channel 'Local/group1@q-groups-d65d,2' has no RTP, not doing anything
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1512[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lmadsen#sokol-084d3040'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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-084d3040, SIP callid 57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99)
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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 '57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99' of Request 102: Match Not Found
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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-084d3040
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1512[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'SIP/lholmes#telcel-084eeae0'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3180[0;37;40m [1;37;40msip_hangup[0;37;40m:  Hangup call SIP/lholmes#telcel-084eeae0, SIP callid 528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99)
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lholmes%23telcel is not a local device, no call limit
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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 '528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99' of Request 102: Match Not Found
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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/lholmes#telcel-084eeae0
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mapp_dial.c[0;37;40m:[1;37;40m1630[0;37;40m [1;37;40mdial_exec_full[0;37;40m:  Exiting with DIALSTATUS=CANCEL.
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m2280[0;37;40m [1;37;40m__ast_pbx_run[0;37;40m:  Spawn extension (q-groups,group1,2) exited non-zero on 'Local/group1@q-groups-d65d,2'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '"Leif Madsen" <lmadsen#sokol>'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'lmadsen#sokol'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'group1'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'q-groups'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'Local/group1@q-groups-d65d,2'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'SIP/lmadsen#telcel-084d6f20'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'Dial'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'SIP/lholmes#telcel&SIP/lmadsen#sokol&SIP/lmadsen#telcel'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '2006-09-03 14:25:25'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '2006-09-03 14:25:32'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '7'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '0'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'BUSY'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is 'DOCUMENTATION'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is '1157307925.6'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mpbx.c[0;37;40m:[1;37;40m1538[0;37;40m [1;37;40mpbx_substitute_variables_helper_full[0;37;40m:  Function result is ''
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [1;37;40mchannel.c[0;37;40m:[1;37;40m1512[0;37;40m [1;37;40mast_hangup[0;37;40m:  Hanging up channel 'Local/group1@q-groups-d65d,2'
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7029]: [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 Local/group1@q-groups-d65d,2
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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 Local - group1@q-groups
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_local.c[0;37;40m:[1;37;40m144[0;37;40m [1;37;40mlocal_devicestate[0;37;40m:  Checking if extension group1@q-groups exists (devicestate)
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for Local/group1@q-groups - state 1 (Not in use)
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lmadsen#sokol
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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 - lholmes#telcel
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lholmes#telcel
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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/lholmes#telcel - state 1 (Not in use)
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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 - lholmes#telcel
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40msip_devicestate[0;37;40m:  Checking device state for peer lholmes#telcel
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [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 Local - group1@q-groups
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mchan_local.c[0;37;40m:[1;37;40m144[0;37;40m [1;37;40mlocal_devicestate[0;37;40m:  Checking if extension group1@q-groups exists (devicestate)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6814]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m:  Changing state for Local/group1@q-groups - state 1 (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7034]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'Local/group1@q-groups' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7035]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7036]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lmadsen#sokol' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7037]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'SIP/lholmes#telcel' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[7038]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m540[0;37;40m [1;37;40mchangethread[0;37;40m:  Device 'Local/group1@q-groups' changed to state '1' (Not in use)
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14046[0;37;40m [1;37;40mhandle_request[0;37;40m:  **** Received ACK (6) - Command in SIP ACK
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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 '0F800478-859D-1136-994C-14164011A83C@192.168.1.101' of Response 11321: Match Not Found
 Really destroying SIP dialog '0F800478-859D-1136-994C-14164011A83C@192.168.1.101' Method: ACK
 [Ktampa99*CLI> [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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 '57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99' of Request 102: Match Found
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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 '57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99' of Request 102: Match Not Found
 Really destroying SIP dialog '57cf77fe563f9e136c1e1a3e73c6e504@8.7.177.99' Method: INVITE
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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 '528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99' of Request 102: Match Found
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2906[0;37;40m [1;37;40mupdate_call_counter[0;37;40m:  lholmes%23telcel is not a local device, no call limit
 [Sep  3 14:25:32] [1;32;40mDEBUG[0;37;40m[6833]: [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 '528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99' of Request 102: Match Not Found
 Really destroying SIP dialog '528eb26a1bec5fd334b82e6a72d7d7b0@8.7.177.99' Method: INVITE
 [Ktampa99*CLI> exit
Executing last minute cleanups
Asterisk ending (0).