##################################################################################################
################################ CALL SCHEME  ####################################################
##################################################################################################

200 (Aastra 57i CT) call's 205 (Polycom 601) and 205 transfers a call to 206 (Plycom 650)

##################################################################################################



<<< Log from 192.168.1.160 started January 08, 2008, 19:43:23 >>>
[test.onnet.su ~]# asterisk -r                                                                                                                                                    
Asterisk 1.4.16-1 RPM by vc-rpms@voipconsulting.nl, Copyright (C) 1999 - 2007 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>                                     
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core 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 'core show license' for details.                         
=========================================================================         
Connected to Asterisk 1.4.16-1 RPM by vc-rpms@voipconsulting.nl currently running on test (pid = 2187)
test*CLI> 
test*CLI> 
test*CLI> core set debug 9
Core debug was 0 and is now 9
test*CLI> 
test*CLI> 
test*CLI> 
test*CLI> 
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 6c9e05b943f0fff2 (Checking From) --From tag 6d8a3e6bbf --To-tag   
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: e3d9c3f07fa71d00 Their Tag 6011e841de Our tag: as5763535c
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 0e05db83e0237be9 Their Tag fdcfb8e23c Our tag: as5889d779
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to Off
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 6c9e05b943f0fff2 - INVITE (With RTP)
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 6c9e05b943f0fff2 (Checking From) --From tag 6d8a3e6bbf --To-tag as694613c3  
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as694613c3
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '6c9e05b943f0fff2' of Response 24264: Match Not Found
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 6c9e05b943f0fff2 (Checking From) --From tag 6d8a3e6bbf --To-tag   
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as694613c3
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel <none>
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:13833 handle_request_invite: Checking SIP call limits for device 200
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:3250 update_call_counter: Call from peer '200' is 1 out of 50
[Jan  8 19:43:42] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/200
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:3993 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) 
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:3995 sip_new: *** Our capabilities are 0xc (ulaw|alaw) 
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4019 sip_new: This channel will not be able to handle video.
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:8245 build_route: build_route: Contact hop: 200 Secretar <sip:200@192.168.1.195:5060;transport=udp>
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:13912 handle_request_invite: SIP/200-08c56ee8: New call is still down.... Trying... 
[Jan  8 19:43:42] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/200-08c56ee8
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/200 - state 2 (In use)
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/200 - state 2 (In use)
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:42] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/200' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:43:42] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/200' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is 'device'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:6028 pbx_builtin_gotoif: Not taking any branch
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'ExecIf'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: ExecIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200 Secretar'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:6028 pbx_builtin_gotoif: Not taking any branch
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '200'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '200/language' in family 'AMPUSER'
[Jan  8 19:43:42] DEBUG[8608]: func_db.c:70 function_db_read: DB: AMPUSER/200/language not found in database.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '200/language' in family 'AMPUSER'
[Jan  8 19:43:42] DEBUG[8608]: func_db.c:70 function_db_read: DB: AMPUSER/200/language not found in database.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'ExecIf'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: ExecIf
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '200/language' in family 'AMPUSER'
[Jan  8 19:43:42] DEBUG[8608]: func_db.c:70 function_db_read: DB: AMPUSER/200/language not found in database.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '200/language' in family 'AMPUSER'
[Jan  8 19:43:42] DEBUG[8608]: func_db.c:70 function_db_read: DB: AMPUSER/200/language not found in database.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:6028 pbx_builtin_gotoif: Not taking any branch
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '-1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '64'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '"200 Secretar" <200>'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Macro
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '205' in family 'CFU'
[Jan  8 19:43:42] DEBUG[8608]: func_db.c:70 function_db_read: DB: CFU/205 not found in database.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '205' in family 'CFB'
[Jan  8 19:43:42] DEBUG[8608]: func_db.c:70 function_db_read: DB: CFB/205 not found in database.
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '""'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '20080108-194342'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'AGI'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: AGI
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: Macro
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'AGI'
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 0e05db83e0237be9 (Checking To) --From tag as5889d779 --To-tag fdcfb8e23c  
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: e3d9c3f07fa71d00 Their Tag 6011e841de Our tag: as5763535c
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 0e05db83e0237be9 Their Tag fdcfb8e23c Our tag: as5889d779
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '0e05db83e0237be9' of Request 247: Match Not Found
[Jan  8 19:43:42] DEBUG[8611]: manager.c:2107 process_message: Manager received command 'login'
[Jan  8 19:43:42] DEBUG[8611]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager.conf
[Jan  8 19:43:42] DEBUG[8611]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager_additional.conf
[Jan  8 19:43:42] DEBUG[8611]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager_custom.conf
[Jan  8 19:43:42] DEBUG[8611]: acl.c:200 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
[Jan  8 19:43:42] DEBUG[8611]: acl.c:200 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
[Jan  8 19:43:42] DEBUG[8611]: acl.c:215 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0
[Jan  8 19:43:42] DEBUG[8611]: acl.c:215 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '205' in family 'CF'
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '205' in family 'DND'
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '205' in family 'CFB'
[Jan  8 19:43:42] DEBUG[8608]: db.c:198 ast_db_get: Unable to find key '205' in family 'CFU'
[Jan  8 19:43:42] DEBUG[8611]: manager.c:2107 process_message: Manager received command 'ExtensionState'
[Jan  8 19:43:42] DEBUG[8611]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:42] DEBUG[8611]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:42] DEBUG[8611]: manager.c:2107 process_message: Manager received command 'Logoff'
[Jan  8 19:43:42] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: AGI
[Jan  8 19:43:42] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Dial'
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:15849 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3993 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3995 sip_new: *** Our capabilities are 0xc (ulaw|alaw) 
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3998 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:4019 sip_new: This channel will not be able to handle video.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable AGISTATUS.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ds.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3612 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ARG3.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ARG2.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable RT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable CFBEXT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable CFUEXT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable EXTTOCALL.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable VMBOX.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable FROMCONTEXT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3612 ast_channel_inherit_variables: Copying hard-transferable variable TTL.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable DB_RESULT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable AMPUSERCID.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable AMPUSER.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jan  8 19:43:42] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:2991 sip_call: Outgoing Call for 205
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3250 update_call_counter: Call to peer '205' is 1 out of 50
[Jan  8 19:43:42] DEBUG[8608]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/205
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/205 - state 6 (Ringing)
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:42] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/205' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:3006 sip_call: Our T38 capability (0), joint T38 capability (0)
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:6425 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:6426 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:6557 add_sdp: -- Done with adding codecs to SDP
[Jan  8 19:43:42] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:42] DEBUG[8608]: chan_sip.c:6602 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 (Checking To) --From tag as1e6bdb49 --To-tag 1C2A
C118-3C5B7C7D  
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 Their Tag  Our tag: as1e6bdb49
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '23381d512fffee357d1f39957197881e@192.168.1.160' Re
quest 102: Found
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:11973 handle_response_invite: SIP response 100 to standard invite
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 (Checking To) --From tag as1e6bdb49 --To-tag 1C2A
C118-3C5B7C7D  
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 Their Tag 1C2AC118-3C5B7C7D Our tag: as1e6bdb49
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '23381d512fffee357d1f39957197881e@192.168.1.160' Re
quest 102: Found
[Jan  8 19:43:42] DEBUG[2213]: chan_sip.c:11973 handle_response_invite: SIP response 180 to standard invite
[Jan  8 19:43:42] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/205-08be9f98
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/205 - state 6 (Ringing)
[Jan  8 19:43:42] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:42] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:42] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/205' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 (Checking To) --From tag as1e6bdb49 --To-tag 1C2A
C118-3C5B7C7D  
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 Their Tag 1C2AC118-3C5B7C7D Our tag: as1e6bdb49
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:2152 __sip_ack: Acked pending invite 102
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '23381d512fffee357d1f39957197881e@192.168.1.160' of Request 102: Match Not Found
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:11973 handle_response_invite: SIP response 200 to standard invite
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel SIP/205-08be9f98
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:5475 process_sdp: We have an owner, now see if we need to change this call
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jan  8 19:43:51] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/205
[Jan  8 19:43:51] DEBUG[2213]: chan_sip.c:8245 build_route: build_route: Contact hop: <sip:205@192.168.1.194>
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:51] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/205 - state 2 (In use)
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:51] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:51] DEBUG[8608]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/205-08be9f98
[Jan  8 19:43:51] DEBUG[8608]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/200-08c56ee8
[Jan  8 19:43:51] DEBUG[8608]: chan_sip.c:3647 sip_answer: SIP answering channel: SIP/200-08c56ee8
[Jan  8 19:43:51] DEBUG[8608]: chan_sip.c:6661 transmit_response_with_sdp: Setting framing from config on incoming call
[Jan  8 19:43:51] DEBUG[8608]: chan_sip.c:6425 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Jan  8 19:43:51] DEBUG[8608]: chan_sip.c:6426 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jan  8 19:43:51] DEBUG[8608]: chan_sip.c:6557 add_sdp: -- Done with adding codecs to SDP
[Jan  8 19:43:51] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:51] DEBUG[8608]: chan_sip.c:6602 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Jan  8 19:43:51] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/205' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:51] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/205 - state 2 (In use)
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:43:51] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:51] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/200 - state 2 (In use)
[Jan  8 19:43:51] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:43:51] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:43:51] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/205' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:43:51] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/200' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:43:52] DEBUG[8608]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan  8 19:43:52] DEBUG[8608]: rtp.c:2776 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan  8 19:43:52] DEBUG[8608]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan  8 19:43:52] DEBUG[8608]: rtp.c:2776 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan  8 19:43:52] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 6c9e05b943f0fff2 (Checking From) --From tag 6d8a3e6bbf --To-tag as6ae21923  
[Jan  8 19:43:52] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 Their Tag 1C2AC118-3C5B7C7D Our tag: as1e6bdb49
[Jan  8 19:43:52] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:43:52] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jan  8 19:43:52] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '6c9e05b943f0fff2' of Response 24265: Match Not Found
[Jan  8 19:43:52] DEBUG[8608]: rtp.c:879 ast_rtcp_read: Got RTCP report of 64 bytes
[Jan  8 19:43:52] DEBUG[8608]: rtp.c:879 ast_rtcp_read: Got RTCP report of 84 bytes
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.1.194
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4172 ast_generic_bridge: Got DTMF begin on channel (SIP/205-08be9f98)
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels SIP/200-08c56ee8 and SIP/205-08be9f98
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.1.194
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4172 ast_generic_bridge: Got DTMF end on channel (SIP/205-08be9f98)
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels SIP/200-08c56ee8 and SIP/205-08be9f98
[Jan  8 19:43:55] DEBUG[8608]: res_features.c:1073 ast_feature_interpret: Feature interpret: chan=SIP/200-08c56ee8, peer=SIP/205-08be9f98, sense=2, features=2 dynamic=(null)
[Jan  8 19:43:55] DEBUG[8608]: res_features.c:1567 ast_bridge_call: Set time limit to 5000
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.1.194
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4172 ast_generic_bridge: Got DTMF begin on channel (SIP/205-08be9f98)
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels SIP/200-08c56ee8 and SIP/205-08be9f98
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.1.194
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4172 ast_generic_bridge: Got DTMF end on channel (SIP/205-08be9f98)
[Jan  8 19:43:55] DEBUG[8608]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels SIP/200-08c56ee8 and SIP/205-08be9f98
[Jan  8 19:43:55] DEBUG[8608]: res_features.c:1073 ast_feature_interpret: Feature interpret: chan=SIP/200-08c56ee8, peer=SIP/205-08be9f98, sense=2, features=2 dynamic=(null)
[Jan  8 19:43:55] DEBUG[8608]: res_features.c:772 builtin_atxfer: Executing Attended Transfer SIP/200-08c56ee8, SIP/205-08be9f98 (sense=2) 
[Jan  8 19:43:55] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  8 19:43:55] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format slin
[Jan  8 19:43:55] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:55] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:3066 set_format: Set channel SIP/200-08c56ee8 to write format slin
[Jan  8 19:43:56] DEBUG[2573]: res_musiconhold.c:266 ast_moh_files_next: SIP/200-08c56ee8 Opened file 1 '/var/lib/asterisk/mohmp3//fpm-calm-river'
[Jan  8 19:43:56] DEBUG[2573]: rtp.c:2629 ast_rtp_raw_write: Difference is 3096, ms is 407
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2184 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 26 sample intervals
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:56] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format ulaw
[Jan  8 19:43:56] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format slin
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2184 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:56] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:56] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: rtp.c:879 ast_rtcp_read: Got RTCP report of 64 bytes
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 192.168.1.194
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 192.168.1.194
[Jan  8 19:43:57] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format ulaw
[Jan  8 19:43:57] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[8608]: rtp.c:879 ast_rtcp_read: Got RTCP report of 84 bytes
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:57] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 192.168.1.194
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 192.168.1.194
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at 192.168.1.194
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at 192.168.1.194
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable BRIDGEPEER.
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3617 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3612 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID.
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3612 ast_channel_inherit_variables: Copying hard-transferable variable TTL.
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2630 ast_indicate_data: Driver for channel 'SIP/205-08be9f98' does not support indication 3, emulating it
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format slin
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '205'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '205'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '205'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:6028 pbx_builtin_gotoif: Not taking any branch
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '63'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '63'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '"" <205>'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Macro
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: db.c:198 ast_db_get: Unable to find key '206' in family 'CFU'
[Jan  8 19:43:58] DEBUG[8612]: func_db.c:70 function_db_read: DB: CFU/206 not found in database.
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: db.c:198 ast_db_get: Unable to find key '206' in family 'CFB'
[Jan  8 19:43:58] DEBUG[8612]: func_db.c:70 function_db_read: DB: CFB/206 not found in database.
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is ''
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '""'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Set'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Set
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1676 pbx_substitute_variables_helper_full: Function result is '20080108-194358'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'AGI'
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:2629 ast_rtp_raw_write: Difference is 7832, ms is 999
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2184 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: AGI
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'NoOp'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Noop
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: Macro
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'AGI'
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[8615]: manager.c:2107 process_message: Manager received command 'login'
[Jan  8 19:43:58] DEBUG[8615]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager.conf
[Jan  8 19:43:58] DEBUG[8615]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager_additional.conf
[Jan  8 19:43:58] DEBUG[8615]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager_custom.conf
[Jan  8 19:43:58] DEBUG[8615]: acl.c:200 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
[Jan  8 19:43:58] DEBUG[8615]: acl.c:200 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
[Jan  8 19:43:58] DEBUG[8615]: acl.c:215 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0
[Jan  8 19:43:58] DEBUG[8615]: acl.c:215 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0
[Jan  8 19:43:58] DEBUG[8612]: db.c:198 ast_db_get: Unable to find key '206' in family 'CF'
[Jan  8 19:43:58] DEBUG[8612]: db.c:198 ast_db_get: Unable to find key '206' in family 'DND'
[Jan  8 19:43:58] DEBUG[8612]: db.c:198 ast_db_get: Unable to find key '206' in family 'CFB'
[Jan  8 19:43:58] DEBUG[8612]: db.c:198 ast_db_get: Unable to find key '206' in family 'CFU'
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8615]: manager.c:2107 process_message: Manager received command 'ExtensionState'
[Jan  8 19:43:58] DEBUG[8615]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:43:58] DEBUG[8615]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:43:58] DEBUG[8615]: manager.c:2107 process_message: Manager received command 'Logoff'
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: AGI
[Jan  8 19:43:58] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Dial'
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:15849 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3993 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3995 sip_new: *** Our capabilities are 0xc (ulaw|alaw) 
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3998 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:4019 sip_new: This channel will not be able to handle video.
[Jan  8 19:43:58] DEBUG[8612]: rtp.c:1586 ast_rtp_make_compatible: Channel 'Local/206@from-internal-xfer-e154,2' has no RTP, not doing anything
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable AGISTATUS.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ds.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3612 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ARG3.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ARG2.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable RT.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable CFBEXT.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable CFUEXT.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable EXTTOCALL.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable VMBOX.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable FROMCONTEXT.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3612 ast_channel_inherit_variables: Copying hard-transferable variable TTL.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable AMPUSER.
[Jan  8 19:43:58] DEBUG[8612]: channel.c:3617 ast_channel_inherit_variables: Not copying variable TRANSFERERNAME.
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:2991 sip_call: Outgoing Call for 206
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3250 update_call_counter: Call to peer '206' is 1 out of 50
[Jan  8 19:43:58] DEBUG[8612]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/206
[Jan  8 19:43:58] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:43:58] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:43:58] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/206 - state 6 (Ringing)
[Jan  8 19:43:58] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:43:58] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:43:58] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/206' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:3006 sip_call: Our T38 capability (0), joint T38 capability (0)
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:6425 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:6426 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:6557 add_sdp: -- Done with adding codecs to SDP
[Jan  8 19:43:58] DEBUG[8612]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=39)
[Jan  8 19:43:58] DEBUG[8612]: chan_sip.c:6602 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2630 ast_indicate_data: Driver for channel 'SIP/205-08be9f98' does not support indication 3, emulating it
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format ulaw
[Jan  8 19:43:58] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format slin
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 (Checking To) --From tag as5fbb7c5b --To-tag 551A
D895-A069933A  
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag  Our tag: as5fbb7c5b
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160' Re
quest 102: Found
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:11973 handle_response_invite: SIP response 100 to standard invite
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2184 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 (Checking To) --From tag as5fbb7c5b --To-tag 551A
D895-A069933A  
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160' Re
quest 102: Found
[Jan  8 19:43:58] DEBUG[2213]: chan_sip.c:11973 handle_response_invite: SIP response 180 to standard invite
[Jan  8 19:43:58] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/206-08c6d540
[Jan  8 19:43:58] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:43:58] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:43:58] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/206 - state 6 (Ringing)
[Jan  8 19:43:58] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:43:58] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:43:58] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/206' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan  8 19:43:58] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:58] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:43:59] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:43:59] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:00] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:00] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:01] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:01] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[2573]: rtp.c:879 ast_rtcp_read: Got RTCP report of 64 bytes
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: rtp.c:879 ast_rtcp_read: Got RTCP report of 84 bytes
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:02] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:02] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:03] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:03] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 114e88f1-8dab6473-f8b0ab5c@192.168.1.194 (Checking From) --From tag 972FE025-5D1C42E6 --To-tag  
 
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 Their Tag 1C2AC118-3C5B7C7D Our tag: as1e6bdb49
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: e3d9c3f07fa71d00 Their Tag 6011e841de Our tag: as5763535c
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 0e05db83e0237be9 Their Tag fdcfb8e23c Our tag: as5889d779
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 114e88f1-8dab6473-f8b0ab5c@192.168.1.194 - SUBSCRIBE (No RTP)
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 114e88f1-8dab6473-f8b0ab5c@192.168.1.194 (Checking From) --From tag 972FE025-5D1C42E6 --To-tag  
 
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 114e88f1-8dab6473-f8b0ab5c@192.168.1.194 Their Tag 972FE025-5D1C42E6 Our tag: as317313de
[Jan  8 19:44:04] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
Really destroying SIP dialog '114e88f1-8dab6473-f8b0ab5c@192.168.1.194' Method: SUBSCRIBE
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:04] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:04] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[2213]: chan_sip.c:2091 __sip_autodestruct: Auto destroying SIP dialog 'e3d9c3f07fa71d00'
[Jan  8 19:44:05] DEBUG[2213]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog e3d9c3f07fa71d00
Really destroying SIP dialog 'e3d9c3f07fa71d00' Method: REGISTER
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:05] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:05] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[2573]: channel.c:2576 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30)
[Jan  8 19:44:06] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 (Checking From) --From tag 1C2AC118-3C5B7C7D --To
-tag as1e6bdb49  
[Jan  8 19:44:06] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:44:06] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 23381d512fffee357d1f39957197881e@192.168.1.160 Their Tag 1C2AC118-3C5B7C7D Our tag: as1e6bdb49
[Jan  8 19:44:06] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received BYE (8) - Command in SIP BYE
[Jan  8 19:44:06] DEBUG[2213]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 23381d512fffee357d1f39957197881e@192.168.1.160
[Jan  8 19:44:06] DEBUG[2213]: chan_sip.c:14705 handle_request_bye: Received bye, issuing owner hangup
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/205-08be9f98 to write format ulaw
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3066 set_format: Set channel SIP/200-08c56ee8 to write format ulaw
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3550 ast_channel_masquerade: Planning to masquerade channel SIP/200-08c56ee8 into the structure of Transfered/SIP/200-08c56ee8
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3564 ast_channel_masquerade: Done planning to masquerade channel SIP/200-08c56ee8 into the structure of Transfered/SIP/200-08c56ee8
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3675 ast_do_masquerade: Actually Masquerading SIP/200-08c56ee8(6) into the structure of Transfered/SIP/200-08c56ee8(6)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3687 ast_do_masquerade: Got clone lock for masquerade on 'SIP/200-08c56ee8' at 0x8c4d820
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3890 ast_do_masquerade: Putting channel SIP/200-08c56ee8 in 4/4 formats
[Jan  8 19:44:06] DEBUG[8608]: chan_sip.c:3772 sip_fixup: SIP Fixup: New owner for dialogue 6c9e05b943f0fff2: SIP/200-08c56ee8 (Old parent: Transfered/SIP/200-08c56ee8<ZOMBIE>)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3930 ast_do_masquerade: Released clone lock on 'Transfered/SIP/200-08c56ee8<ZOMBIE>'
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3940 ast_do_masquerade: Done Masquerading SIP/200-08c56ee8 (6)
[Jan  8 19:44:06] DEBUG[8608]: channel.c:3066 set_format: Set channel Local/206@from-internal-xfer-e154,1 to write format slin
[Jan  8 19:44:06] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 160 sample intervals
[Jan  8 19:44:07] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 22 sample intervals
[Jan  8 19:44:07] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:44:07] DEBUG[8608]: channel.c:2095 ast_settimeout: Scheduling timer at 0 sample intervals
[Jan  8 19:44:07] DEBUG[8608]: channel.c:3066 set_format: Set channel Local/206@from-internal-xfer-e154,1 to write format ulaw
[Jan  8 19:44:07] DEBUG[8608]: channel.c:1786 ast_hangup: Hanging up channel 'SIP/205-08be9f98'
[Jan  8 19:44:07] DEBUG[8608]: chan_sip.c:3485 sip_hangup: Hangup call SIP/205-08be9f98, SIP callid 23381d512fffee357d1f39957197881e@192.168.1.160)
[Jan  8 19:44:07] DEBUG[8608]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jan  8 19:44:07] DEBUG[8608]: chan_sip.c:3224 update_call_counter: Call to peer '205' removed from call limit 50
[Jan  8 19:44:07] DEBUG[8608]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/205
[Jan  8 19:44:07] DEBUG[8608]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/205-08be9f98
[Jan  8 19:44:07] DEBUG[8608]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Transfered/SIP/200-08c56ee8<ZOMBIE>' has no RTP, not doing anything
[Jan  8 19:44:07] DEBUG[8608]: app_dial.c:1736 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:329 _macro_exec: Spawn extension (macro-dial,s,7) exited non-zero on 'Transfered/SIP/200-08c56ee8<ZOMBIE>' in macro 'dial'
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:329 _macro_exec: Spawn extension (macro-dial,s,7) exited non-zero on 'Transfered/SIP/200-08c56ee8<ZOMBIE>' in macro 'exten-vm'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:2425 __ast_pbx_run: Spawn extension (macro-dial,s,7) exited non-zero on 'Transfered/SIP/200-08c56ee8<ZOMBIE>'
[Jan  8 19:44:07] DEBUG[8608]: channel.c:1567 ast_softhangup_nolock: Soft-Hanging up channel 'Transfered/SIP/200-08c56ee8<ZOMBIE>'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'ResetCDR'
[Jan  8 19:44:07] DEBUG[8608]: cdr_addon_mysql.c:217 mysql_log: cdr_mysql: inserting a CDR record.
[Jan  8 19:44:07] DEBUG[8608]: cdr_addon_mysql.c:234 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,last
data,duration,billsec,disposition,amaflags,accountcode) VALUES ('2008-01-08 19:43:42','','','205','from-internal', 'Transfered/SIP/200-08c56ee8<ZOMBIE>','SIP/205-08be9f98','','',
25,16,'ANSWERED',3,'')
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:44:07] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/205 - state 1 (Not in use)
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:44:07] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:44:07] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/205' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: ResetCDR
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'NoCDR'
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: NoCDR
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:1827 pbx_extension_helper: Launching 'Hangup'
[Jan  8 19:44:07] DEBUG[8608]: app_macro.c:329 _macro_exec: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'Transfered/SIP/200-08c56ee8<ZOMBIE>' in macro 'hangupcall'
[Jan  8 19:44:07] DEBUG[8608]: pbx.c:2548 __ast_pbx_run: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'Transfered/SIP/200-08c56ee8<ZOMBIE>'
[Jan  8 19:44:07] DEBUG[8608]: channel.c:1791 ast_hangup: Hanging up zombie 'Transfered/SIP/200-08c56ee8<ZOMBIE>'
[Jan  8 19:44:07] DEBUG[8608]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Transfered/SIP/200-08c56ee8<ZOMBI
E>
[Jan  8 19:44:07] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/205 - state 1 (Not in use)
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 205
[Jan  8 19:44:07] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 205
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Transfered - SIP/200
[Jan  8 19:44:07] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for Transfered/SIP/200 - state 4 (Invalid)
[Jan  8 19:44:07] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/205' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:07] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'Transfered/SIP/200' changed to state '4' (Invalid) but we don't care because they're not a member of an
y queue.
[Jan  8 19:44:07] DEBUG[8616]: rtp.c:879 ast_rtcp_read: Got RTCP report of 64 bytes
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Really destroying SIP dialog '23381d512fffee357d1f39957197881e@192.168.1.160' Method: BYE
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 28ec4df432e0879306ed9b977ad753ea@192.168.1.160 (Checking To) --From tag as67781f7b --To-tag F053
7D78-83CEF471  
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 28ec4df432e0879306ed9b977ad753ea@192.168.1.160 Their Tag  Our tag: as67781f7b
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '28ec4df432e0879306ed9b977ad753ea@192.168.1.160' of Request 102: Match Not Found
Really destroying SIP dialog '28ec4df432e0879306ed9b977ad753ea@192.168.1.160' Method: OPTIONS
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 4693e870488c85340596807b6927580b@192.168.1.160 (Checking To) --From tag as088788fb --To-tag F262
576E-1776BD5B  
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 4693e870488c85340596807b6927580b@192.168.1.160 Their Tag  Our tag: as088788fb
[Jan  8 19:44:07] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '4693e870488c85340596807b6927580b@192.168.1.160' of Request 102: Match Not Found
Really destroying SIP dialog '4693e870488c85340596807b6927580b@192.168.1.160' Method: OPTIONS
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 3eba63f4258847650df66a262e01979a@192.168.1.160 (Checking To) --From tag as36956dca --To-tag 1411
336378  
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 3eba63f4258847650df66a262e01979a@192.168.1.160 Their Tag  Our tag: as36956dca
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '3eba63f4258847650df66a262e01979a@192.168.1.160' of Request 102: Match Not Found
Really destroying SIP dialog '3eba63f4258847650df66a262e01979a@192.168.1.160' Method: OPTIONS
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 1e4a67095cdeb20761e303f014e12659@192.168.1.160 (Checking To) --From tag as0c04516e --To-tag d34d
d3b1c84993b  
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 62be0c6129ff2e1962946bda126d6f38@192.168.1.160 Their Tag  Our tag: as73c33646
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 1e4a67095cdeb20761e303f014e12659@192.168.1.160 Their Tag  Our tag: as0c04516e
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '1e4a67095cdeb20761e303f014e12659@192.168.1.160' of Request 102: Match Not Found
Really destroying SIP dialog '1e4a67095cdeb20761e303f014e12659@192.168.1.160' Method: OPTIONS
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 62be0c6129ff2e1962946bda126d6f38@192.168.1.160 (Checking To) --From tag as73c33646 --To-tag 2954
917821  
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 62be0c6129ff2e1962946bda126d6f38@192.168.1.160 Their Tag  Our tag: as73c33646
[Jan  8 19:44:08] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '62be0c6129ff2e1962946bda126d6f38@192.168.1.160' of Request 102: Match Not Found
Really destroying SIP dialog '62be0c6129ff2e1962946bda126d6f38@192.168.1.160' Method: OPTIONS
[Jan  8 19:44:09] DEBUG[2996]: manager.c:2107 process_message: Manager received command 'Command'
[Jan  8 19:44:09] DEBUG[2996]: manager.c:2107 process_message: Manager received command 'Command'
[Jan  8 19:44:09] DEBUG[2996]: manager.c:2107 process_message: Manager received command 'Command'
[Jan  8 19:44:12] DEBUG[8616]: rtp.c:879 ast_rtcp_read: Got RTCP report of 40 bytes
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: bdce0fd3a41b6d55 (Checking From) --From tag 153dee89bf --To-tag   
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 0e05db83e0237be9 Their Tag fdcfb8e23c Our tag: as5889d779
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for bdce0fd3a41b6d55 - REGISTER (No RTP)
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: bdce0fd3a41b6d55 (Checking From) --From tag 153dee89bf --To-tag   
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: bdce0fd3a41b6d55 Their Tag 153dee89bf Our tag: as60132dcc
[Jan  8 19:44:13] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
[Jan  8 19:44:13] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/200
[Jan  8 19:44:13] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:13] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:13] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/200 - state 2 (In use)
[Jan  8 19:44:13] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:13] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/200' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:13] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:17] DEBUG[8616]: rtp.c:879 ast_rtcp_read: Got RTCP report of 40 bytes
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 (Checking To) --From tag as5fbb7c5b --To-tag 551A
D895-A069933A  
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: bdce0fd3a41b6d55 Their Tag 153dee89bf Our tag: as60132dcc
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:2152 __sip_ack: Acked pending invite 102
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160' of Request 102: Match Not Found
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:11973 handle_response_invite: SIP response 200 to standard invite
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel SIP/206-08c6d540
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:5475 process_sdp: We have an owner, now see if we need to change this call
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jan  8 19:44:19] DEBUG[2213]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/206
[Jan  8 19:44:19] DEBUG[2213]: chan_sip.c:8245 build_route: build_route: Contact hop: <sip:206@192.168.1.193>
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:19] DEBUG[8612]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/206-08c6d540
[Jan  8 19:44:19] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/206 - state 2 (In use)
[Jan  8 19:44:19] DEBUG[8612]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/206@from-internal-xfer-e154
,2
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:19] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:19] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/206 - state 2 (In use)
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:19] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 206@from-internal-xfer
[Jan  8 19:44:19] DEBUG[2197]: chan_local.c:145 local_devicestate: Checking if extension 206@from-internal-xfer exists (devicestate)
[Jan  8 19:44:19] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for Local/206@from-internal-xfer - state 2 (In use)
[Jan  8 19:44:19] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/206' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:19] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/206' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:19] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'Local/206@from-internal-xfer' changed to state '2' (In use) but we don't care because they're not a mem
ber of any queue.
[Jan  8 19:44:19] DEBUG[8616]: channel.c:4149 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/206@from-internal-xfer-e154,1
[Jan  8 19:44:19] DEBUG[8616]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels Local/206@from-internal-xfer-e154,1 and SIP/200-08c56ee8
[Jan  8 19:44:19] DEBUG[8616]: channel.c:2354 __ast_read: Ignoring answer on an inbound call!
[Jan  8 19:44:19] DEBUG[8612]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Jan  8 19:44:19] DEBUG[8612]: rtp.c:2776 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:1922 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #47768)) 
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 3d96948070771c137764b7aa723c0b95@192.168.1.160 (Checking To) --From tag as4facb609 --To-tag 3073
51729  
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 3d96948070771c137764b7aa723c0b95@192.168.1.160 Their Tag  Our tag: as4facb609
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '3d96948070771c137764b7aa723c0b95@192.168.1.160' of Request 102: Match Not Found
Really destroying SIP dialog '3d96948070771c137764b7aa723c0b95@192.168.1.160' Method: NOTIFY
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 3d96948070771c137764b7aa723c0b95@192.168.1.160 (Checking To) --From tag as4facb609 --To-tag 3073
51729  
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: bdce0fd3a41b6d55 Their Tag 153dee89bf Our tag: as60132dcc
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 0e05db83e0237be9 Their Tag fdcfb8e23c Our tag: as5889d779
[Jan  8 19:44:22] DEBUG[2213]: chan_sip.c:15337 sipsock_read: Invalid SIP message - rejected , no callid, len 401
[Jan  8 19:44:22] DEBUG[8616]: rtp.c:879 ast_rtcp_read: Got RTCP report of 64 bytes
[Jan  8 19:44:22] DEBUG[8612]: rtp.c:879 ast_rtcp_read: Got RTCP report of 84 bytes
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 (Checking From) --From tag 551AD895-A069933A --To
-tag as5fbb7c5b  
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: bdce0fd3a41b6d55 Their Tag 153dee89bf Our tag: as60132dcc
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160 Their Tag 551AD895-A069933A Our tag: as5fbb7c5b
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:15153 handle_request: **** Received BYE (8) - Command in SIP BYE
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:14705 handle_request_bye: Received bye, issuing owner hangup
[Jan  8 19:44:25] DEBUG[8612]: channel.c:4126 ast_generic_bridge: Didn't get a frame from channel: SIP/206-08c6d540
[Jan  8 19:44:25] DEBUG[8612]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels Local/206@from-internal-xfer-e154,2 and SIP/206-08c6d540
[Jan  8 19:44:25] DEBUG[8612]: channel.c:1786 ast_hangup: Hanging up channel 'SIP/206-08c6d540'
[Jan  8 19:44:25] DEBUG[8612]: chan_sip.c:3485 sip_hangup: Hangup call SIP/206-08c6d540, SIP callid 08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160)
[Jan  8 19:44:25] DEBUG[8612]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jan  8 19:44:25] DEBUG[8612]: chan_sip.c:3224 update_call_counter: Call to peer '206' removed from call limit 50
[Jan  8 19:44:25] DEBUG[8612]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/206
[Jan  8 19:44:25] DEBUG[8612]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/206-08c6d540
[Jan  8 19:44:25] DEBUG[8612]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/206@from-internal-xfer-e154,2' has no RTP, not doing anything
[Jan  8 19:44:25] DEBUG[8612]: app_dial.c:1736 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:329 _macro_exec: Spawn extension (macro-dial,s,7) exited non-zero on 'Local/206@from-internal-xfer-e154,2' in macro 'dial'
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:329 _macro_exec: Spawn extension (macro-dial,s,7) exited non-zero on 'Local/206@from-internal-xfer-e154,2' in macro 'exten-vm'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:2425 __ast_pbx_run: Spawn extension (macro-dial,s,7) exited non-zero on 'Local/206@from-internal-xfer-e154,2'
[Jan  8 19:44:25] DEBUG[8612]: channel.c:1567 ast_softhangup_nolock: Soft-Hanging up channel 'Local/206@from-internal-xfer-e154,2'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Macro'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'ResetCDR'
[Jan  8 19:44:25] DEBUG[8612]: cdr_addon_mysql.c:217 mysql_log: cdr_mysql: inserting a CDR record.
Really destroying SIP dialog '08dc01d04cbd22cf6149c3664e4ba312@192.168.1.160' Method: BYE
[Jan  8 19:44:25] DEBUG[8612]: cdr_addon_mysql.c:234 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,last
data,duration,billsec,disposition,amaflags,accountcode) VALUES ('2008-01-08 19:43:58','205','205','206','from-internal-xfer', 'Local/206@from-internal-xfer-e154,2','SIP/206-08c6d
540','Dial','SIP/206||Ttr',27,6,'ANSWERED',3,'')
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/206 - state 1 (Not in use)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/206 - state 1 (Not in use)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 206
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 206
[Jan  8 19:44:25] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/206' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:25] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/206' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: ResetCDR
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'NoCDR'
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: NoCDR
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1744 pbx_substitute_variables_helper_full: Expression result is '1'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'GotoIf'
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:337 _macro_exec: Executed application: GotoIf
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:1827 pbx_extension_helper: Launching 'Hangup'
[Jan  8 19:44:25] DEBUG[8612]: app_macro.c:329 _macro_exec: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'Local/206@from-internal-xfer-e154,2' in macro 'hangupcall'
[Jan  8 19:44:25] DEBUG[8612]: pbx.c:2548 __ast_pbx_run: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'Local/206@from-internal-xfer-e154,2'
[Jan  8 19:44:25] DEBUG[8612]: channel.c:1786 ast_hangup: Hanging up channel 'Local/206@from-internal-xfer-e154,2'
[Jan  8 19:44:25] DEBUG[8612]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/206@from-internal-xfer-e154
,2
[Jan  8 19:44:25] DEBUG[8616]: channel.c:4126 ast_generic_bridge: Didn't get a frame from channel: Local/206@from-internal-xfer-e154,1
[Jan  8 19:44:25] DEBUG[8616]: channel.c:4451 ast_channel_bridge: Bridge stops bridging channels Local/206@from-internal-xfer-e154,1 and SIP/200-08c56ee8
[Jan  8 19:44:25] DEBUG[8616]: channel.c:1786 ast_hangup: Hanging up channel 'SIP/200-08c56ee8'
[Jan  8 19:44:25] DEBUG[8616]: chan_sip.c:3485 sip_hangup: Hangup call SIP/200-08c56ee8, SIP callid 6c9e05b943f0fff2)
[Jan  8 19:44:25] DEBUG[8616]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call
[Jan  8 19:44:25] DEBUG[8616]: chan_sip.c:3224 update_call_counter: Call from peer '200' removed from call limit 50
[Jan  8 19:44:25] DEBUG[8616]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/200
[Jan  8 19:44:25] DEBUG[8616]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/200-08c56ee8
[Jan  8 19:44:25] DEBUG[8616]: channel.c:1786 ast_hangup: Hanging up channel 'Local/206@from-internal-xfer-e154,1'
[Jan  8 19:44:25] DEBUG[8616]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/206@from-internal-xfer-e154
,1
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 206@from-internal-xfer
[Jan  8 19:44:25] DEBUG[2197]: chan_local.c:145 local_devicestate: Checking if extension 206@from-internal-xfer exists (devicestate)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for Local/206@from-internal-xfer - state 1 (Not in use)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/200 - state 1 (Not in use)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for SIP/200 - state 1 (Not in use)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 200
[Jan  8 19:44:25] DEBUG[2197]: chan_sip.c:15780 sip_devicestate: Checking device state for peer 200
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 206@from-internal-xfer
[Jan  8 19:44:25] DEBUG[2197]: chan_local.c:145 local_devicestate: Checking if extension 206@from-internal-xfer exists (devicestate)
[Jan  8 19:44:25] DEBUG[2197]: devicestate.c:287 do_state_change: Changing state for Local/206@from-internal-xfer - state 1 (Not in use)
[Jan  8 19:44:25] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'Local/206@from-internal-xfer' changed to state '1' (Not in use) but we don't care because they're not a
 member of any queue.
[Jan  8 19:44:25] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:25] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan  8 19:44:25] DEBUG[2222]: app_queue.c:581 handle_statechange: Device 'Local/206@from-internal-xfer' changed to state '1' (Not in use) but we don't care because they're not a
 member of any queue.
[Jan  8 19:44:25] DEBUG[8616]: cdr_addon_mysql.c:217 mysql_log: cdr_mysql: inserting a CDR record.
[Jan  8 19:44:25] DEBUG[8616]: cdr_addon_mysql.c:234 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,last
data,duration,billsec,disposition,amaflags,accountcode) VALUES ('2008-01-08 19:44:07','205','205','206','from-internal-xfer', 'Local/206@from-internal-xfer-e154,1','SIP/200-08c56
ee8','Dial','Local/206@from-internal-xfer/n',18,18,'ANSWERED',3,'')
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 0e05db83e0237be9 (Checking To) --From tag as5889d779 --To-tag fdcfb8e23c  
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: bdce0fd3a41b6d55 Their Tag 153dee89bf Our tag: as60132dcc
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 0e05db83e0237be9 Their Tag fdcfb8e23c Our tag: as5889d779
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '0e05db83e0237be9' of Request 248: Match Not Found
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4546 find_call: = Looking for  Call ID: 6c9e05b943f0fff2 (Checking To) --From tag as6ae21923 --To-tag 6d8a3e6bbf  
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = No match Their Call ID: bdce0fd3a41b6d55 Their Tag 153dee89bf Our tag: as60132dcc
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:4562 find_call: = Found Their Call ID: 6c9e05b943f0fff2 Their Tag 6d8a3e6bbf Our tag: as6ae21923
[Jan  8 19:44:25] DEBUG[2213]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '6c9e05b943f0fff2' of Request 102: Match Not Found
Really destroying SIP dialog '6c9e05b943f0fff2' Method: ACK
test*CLI> 
test*CLI> 
test*CLI> 
test*CLI> 
<<< Log from 192.168.1.160 ended January 08, 2008, 19:44:38 >>>