[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is '462'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:47] Set("Local/22237@default-queue-9f01,2", "__target_2_num_id=462") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:48] Set("Local/22237@default-queue-9f01,2", "__target_2_ext=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:49] Set("Local/22237@default-queue-9f01,2", "__target_2_ext_id=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_2_disposition' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_2_disposition not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:50] Set("Local/22237@default-queue-9f01,2", "__target_2_disposition=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '3'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:51] Set("Local/22237@default-queue-9f01,2", "i=3") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Goto'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:52] Goto("Local/22237@default-queue-9f01,2", "44") in new stack
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,44)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Goto
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '1'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:44] GotoIf("Local/22237@default-queue-9f01,2", "1?45:53") in new stack
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,45)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is 'queue'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:45] Set("Local/22237@default-queue-9f01,2", "__target_3_type=queue") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is '22901'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:46] Set("Local/22237@default-queue-9f01,2", "__target_3_num=22901") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is '84'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:47] Set("Local/22237@default-queue-9f01,2", "__target_3_num_id=84") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:48] Set("Local/22237@default-queue-9f01,2", "__target_3_ext=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:49] Set("Local/22237@default-queue-9f01,2", "__target_3_ext_id=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_3_disposition' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_3_disposition not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:50] Set("Local/22237@default-queue-9f01,2", "__target_3_disposition=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '4'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:51] Set("Local/22237@default-queue-9f01,2", "i=4") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Goto'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:52] Goto("Local/22237@default-queue-9f01,2", "44") in new stack
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,44)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Goto
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '1'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:44] GotoIf("Local/22237@default-queue-9f01,2", "1?45:53") in new stack
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,45)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_4_type' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_4_type not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:45] Set("Local/22237@default-queue-9f01,2", "__target_4_type=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_4_num' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_4_num not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:46] Set("Local/22237@default-queue-9f01,2", "__target_4_num=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_4_num_id' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_4_num_id not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:47] Set("Local/22237@default-queue-9f01,2", "__target_4_num_id=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_4_ext' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_4_ext not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:48] Set("Local/22237@default-queue-9f01,2", "__target_4_ext=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_4_ext_id' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_4_ext_id not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:49] Set("Local/22237@default-queue-9f01,2", "__target_4_ext_id=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] db.c: Unable to find key '1201811729.186/target_4_disposition' in family 'call_globals'
[Jan 31 12:38:52] DEBUG[1466] func_db.c: DB: call_globals/1201811729.186/target_4_disposition not found in database.
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Function result is ''
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:50] Set("Local/22237@default-queue-9f01,2", "__target_4_disposition=") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '5'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:51] Set("Local/22237@default-queue-9f01,2", "i=5") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Goto'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:52] Goto("Local/22237@default-queue-9f01,2", "44") in new stack
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,44)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Goto
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '0'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:44] GotoIf("Local/22237@default-queue-9f01,2", "0?45:53") in new stack
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,53)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'NoOp'
[Jan 31 12:38:52] DEBUG[1003] channel.c: Scheduling timer at 8 sample intervals
[Jan 31 12:38:52] DEBUG[1003] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 12:38:52] DEBUG[1003] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 12:38:52] DEBUG[1003] channel.c: Scheduling timer at 160 sample intervals
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:53] NoOp("Local/22237@default-queue-9f01,2", "Finish for-read_vars-36") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: NoOp
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '1'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:54] GotoIf("Local/22237@default-queue-9f01,2", "1?55:56") in new stack
[Jan 31 12:38:52] VERBOSE[1003] logger.c:     -- <SIP/112233-070b1368> Playing 'digits/2' (language 'en')
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,55)
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:55] Set("Local/22237@default-queue-9f01,2", "__transfer_count=0") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'NoOp'
[Jan 31 12:38:52] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:56] NoOp("Local/22237@default-queue-9f01,2", "Finish if-read_vars-37") in new stack
[Jan 31 12:38:52] DEBUG[1466] app_macro.c: Executed application: NoOp
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Expression result is '1'
[Jan 31 12:38:52] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:57] GotoIf("Local/22237@default-queue-9f01,2", "1?58:59") in new stack
[Jan 31 12:38:53] ERROR[1389] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 5 sec for mutex '&q->lock'?
[Jan 31 12:38:53] ERROR[1389] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 2662 (try_calling): '&q->lock' was locked here.
[Jan 31 12:38:53] ERROR[1209] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 5 sec for mutex '&q->lock'?
[Jan 31 12:38:53] ERROR[1209] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 2662 (try_calling): '&q->lock' was locked here.
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,58)
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:58] Set("Local/22237@default-queue-9f01,2", "__transfer_back=0") in new stack
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'NoOp'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:59] NoOp("Local/22237@default-queue-9f01,2", "Finish if-read_vars-38") in new stack
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: NoOp
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Expression result is '1'
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:60] GotoIf("Local/22237@default-queue-9f01,2", "1?61:62") in new stack
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,61)
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'Set'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:61] Set("Local/22237@default-queue-9f01,2", "__agent_call_counter_set=0") in new stack
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: Set
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'NoOp'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:62] NoOp("Local/22237@default-queue-9f01,2", "Finish if-read_vars-39") in new stack
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: NoOp
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Expression result is '0'
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:63] GotoIf("Local/22237@default-queue-9f01,2", "0?64:65") in new stack
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Goto (macro-read_vars,s,65)
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: GotoIf
[Jan 31 12:38:53] DEBUG[1466] pbx.c: Launching 'NoOp'
[Jan 31 12:38:53] VERBOSE[1466] logger.c:     -- Executing [s@macro-read_vars:65] NoOp("Local/22237@default-queue-9f01,2", "Finish if-read_vars-40") in new stack
[Jan 31 12:38:53] DEBUG[1466] app_macro.c: Executed application: NoOp
[Jan 31 12:38:54] DEBUG[1466] pbx.c: Expression result is '0'
[Jan 31 12:38:54] DEBUG[1466] pbx.c: Launching 'GotoIf'
[Jan 31 12:38:53] DEBUG[1389] rtp.c: Got RTCP report of 64 bytes
[Jan 31 12:38:53] DEBUG[1003] channel.c: Scheduling timer at 8 sample intervals
[Jan 31 12:38:54] DEBUG[1003] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 12:38:54] DEBUG[1003] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 12:38:54] DEBUG[1003] channel.c: Scheduling timer at 160 sample intervals
[Jan 31 12:38:53] DEBUG[32049] app_queue.c: Device 'Agent/22271' changed to state '1' (Not in use)
[Jan 31 12:38:53] DEBUG[32031] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
[Jan 31 12:38:54] NOTICE[32031] chan_iax2.c: Restricting registration for peer 'iaxmodem1' to 60 seconds (requested 300)
[Jan 31 12:38:54] DEBUG[32031] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 13)
[Jan 31 12:38:54] DEBUG[32031] chan_iax2.c: Acking anyway
[Jan 31 12:38:54] DEBUG[32031] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 13)
[Jan 31 12:38:54] DEBUG[32031] chan_iax2.c: Acking anyway
[Jan 31 12:38:53] DEBUG[1274] app_queue.c: It's our turn (SIP/112233-07020068).
[Jan 31 12:38:54] DEBUG[1274] app_queue.c: SIP/112233-07020068 is trying to call a queue member.
[Jan 31 12:38:54] DEBUG[1274] app_queue.c: Nobody left to try ringing in queue
[Jan 31 12:38:54] DEBUG[1274] app_queue.c: Everyone is busy at this time
[Jan 31 12:38:54] DEBUG[1274] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 12:38:54] DEBUG[1274] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_member_table WHERE interface LIKE '%' AND queue_name = '22902' ORDER BY interface
[Jan 31 12:38:53] WARNING[1418] app_addon_sql_mysql.c: mysql_real_connect(mysql,localhost,asterisk,dbpass,asterisk,...) failed
[Jan 31 12:38:54] DEBUG[1418] app_macro.c: Executed application: MYSQL
[Jan 31 12:38:54] DEBUG[1418] pbx.c: Launching 'MYSQL'
[Jan 31 12:38:53] DEBUG[1241] rtp.c: Got RTCP report of 64 bytes
[Jan 31 12:38:54] DEBUG[1460] pbx.c: Launching 'MYSQL'
[Jan 31 12:38:54] ERROR[1435] /usr/include/asterisk/lock.h: app_addon_sql_mysql.c line 397 (MYSQL_exec): Deadlock? waited 5 sec for mutex '&_mysql_mutex'?
[Jan 31 12:38:54] ERROR[1435] /usr/include/asterisk/lock.h: