[Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:14] NoOp("SIP/112233-06f73180", "Finish if-init_channel-23") in new stack [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:00:59] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:15] GotoIf("SIP/112233-06f73180", "0?16:22") in new stack [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,22) [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:22] NoOp("SIP/112233-06f73180", "Finish if-init_channel-24") in new stack [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:00:59] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:23] GotoIf("SIP/112233-06f73180", "0?24:26") in new stack [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,26) [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:26] NoOp("SIP/112233-06f73180", "Finish if-init_channel-25") in new stack [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:00:59] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:27] GotoIf("SIP/112233-06f73180", "0?28:29") in new stack [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,29) [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:29] NoOp("SIP/112233-06f73180", "Finish if-init_channel-26") in new stack [Jan 31 07:00:59] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:00:59] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:00:59] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:00:59] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:30] GotoIf("SIP/112233-06f73180", "0?31:32") in new stack [Jan 31 07:00:59] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:00:59] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:00:59] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:00] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:00] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:00] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:00] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:00] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:01] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:01] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:01] DEBUG[26753] app_queue.c: It's our turn (SIP/112233-0746d320). [Jan 31 07:01:01] DEBUG[26753] app_queue.c: SIP/112233-0746d320 is trying to call a queue member. [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Trying 'Agent/22206' with metric 998897 [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Agent/22206 paused, can't receive call [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Trying 'Agent/22246' with metric 5998925 [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Agent/22246 paused, can't receive call [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Trying 'Agent/22234' with metric 5999293 [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Trying 'Agent/22254' with metric 5999695 [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Agent/22254 paused, can't receive call [Jan 31 07:01:01] DEBUG[26753] app_queue.c: Nobody left to try ringing in queue [Jan 31 07:01:01] NOTICE[26753] app_queue.c: No one is answering queue '22901' (4/1/0) [Jan 31 07:01:02] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:02] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:02] DEBUG[26305] rtp.c: Sending dtmf: 42 (*), at 81.198.164.48 [Jan 31 07:01:02] DEBUG[26305] rtp.c: Sending dtmf: 42 (*), at 81.198.164.48 [Jan 31 07:01:02] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:03] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:03] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:03] DEBUG[26305] rtp.c: Sending dtmf: 42 (*), at 81.198.164.48 [Jan 31 07:01:03] DEBUG[26305] rtp.c: Sending dtmf: 42 (*), at 81.198.164.48 [Jan 31 07:01:03] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:03] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:03] DEBUG[26832] manager.c: Manager received command 'Login' [Jan 31 07:01:03] DEBUG[26577] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:03] DEBUG[26577] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:03] DEBUG[26577] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,32) [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:32] NoOp("SIP/112233-06f73180", "Finish if-init_channel-27") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:03] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:33] GotoIf("SIP/112233-06f73180", "0?34:35") in new stack [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,35) [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:35] NoOp("SIP/112233-06f73180", "Finish if-init_channel-28") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:03] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:36] GotoIf("SIP/112233-06f73180", "0?37:38") in new stack [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,38) [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:38] NoOp("SIP/112233-06f73180", "Finish if-init_channel-29") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:03] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:39] GotoIf("SIP/112233-06f73180", "0?40:41") in new stack [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,41) [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:41] NoOp("SIP/112233-06f73180", "Finish if-init_channel-30") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:03] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:42] GotoIf("SIP/112233-06f73180", "0?43:44") in new stack [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Goto (macro-init_channel,s,44) [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:44] NoOp("SIP/112233-06f73180", "Finish if-init_channel-31") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:45] Set("SIP/112233-06f73180", "initialized=1") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-init_channel:46] NoOp("SIP/112233-06f73180", "-(E)------------------------------------- macro init_channel -----------") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'Macro' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [17@default-queue:4] Macro("SIP/112233-06f73180", "read_vars") in new stack [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:1] NoOp("SIP/112233-06f73180", "-(B)------------------------------------- macro read_vars (SIP/112233-06f73180) -----------") in new stack [Jan 31 07:01:03] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:03] DEBUG[26704] db.c: Unable to find key '1201791524.235/transfer_count' in family 'call_globals' [Jan 31 07:01:03] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/transfer_count not found in database. [Jan 31 07:01:03] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:03] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:03] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:2] Set("SIP/112233-06f73180", "__transfer_count=") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] db.c: Unable to find key '1201791524.235/agent_call_counter_set' in family 'call_globals' [Jan 31 07:01:04] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/agent_call_counter_set not found in database. [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:3] Set("SIP/112233-06f73180", "__agent_call_counter_set=") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is '22901' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:4] Set("SIP/112233-06f73180", "__call_from_queue=22901") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is '22901' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:5] Set("SIP/112233-06f73180", "__directly_from_queue=22901") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is '1' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:6] Set("SIP/112233-06f73180", "__cdr_block_started=1") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:7] Set("SIP/112233-06f73180", "__xfer_block_started=") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is 'yes' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:8] Set("SIP/112233-06f73180", "__business_hours=yes") in new stack [Jan 31 07:01:04] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:04] DEBUG[26704] db.c: Unable to find key '1201791524.235/agent_auto_pause' in family 'call_globals' [Jan 31 07:01:04] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/agent_auto_pause not found in database. [Jan 31 07:01:04] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:04] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:04] DEBUG[26305] rtp.c: Sending dtmf: 54 (6), at 81.198.164.48 [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '1894487957' [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE host = '81.198.164.48' AND port = '5060' [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE ipaddr = '81.198.164.48' AND port = '5060' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Setting NAT on RTP to On [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '387321955fe03310313cc4a873235ae9@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '3ee4210328bcdce36da78a0238f7dcf4@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '5b0943670ee3da781710fee8472637ec@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '6e7613b3223920764bf742902c00d9ac@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '5ce8e47464f90ae1031cd81414144f90@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '0e86b4a0167d6d9876f697c758264f62@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '59892f9703aa353c21894fa60be83984@127.0.0.1' [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: chan_sip: ast_sched_runq ran 22 all at once [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Stopping retransmission on '4d8d9fde548ff9192c2ad2c7376f1b65@81.198.164.48' of Response 102: Match Not Found [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '1894487957' [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE host = '81.198.164.48' AND port = '5060' [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE ipaddr = '81.198.164.48' AND port = '5060' [Jan 31 07:01:04] DEBUG[26305] rtp.c: Sending dtmf: 54 (6), at 81.198.164.48 [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Setting NAT on RTP to On [Jan 31 07:01:04] DEBUG[24778] chan_sip.c: Checking SIP call limits for device 112233 [Jan 31 07:01:04] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:04] DEBUG[24755] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24755] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '112233-06f611d0' AND host = 'dynamic' [Jan 31 07:01:04] DEBUG[24755] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24755] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '112233-06f611d0' [Jan 31 07:01:04] DEBUG[24755] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:04] DEBUG[24755] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '112233' AND host = 'dynamic' [Jan 31 07:01:04] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:05] DEBUG[26753] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:05] DEBUG[26753] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_member_table WHERE interface LIKE '%' AND queue_name = '22901' ORDER BY interface [Jan 31 07:01:05] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:05] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:05] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:05] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:05] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:05] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:05] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:06] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:06] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:06] VERBOSE[26831] logger.c: == Manager 'admin' logged off from 127.0.0.1 [Jan 31 07:01:06] VERBOSE[26832] logger.c: == Parsing '/etc/asterisk/manager.conf': [Jan 31 07:01:06] DEBUG[26832] config.c: Parsing /etc/asterisk/manager.conf [Jan 31 07:01:06] VERBOSE[26832] logger.c: Found [Jan 31 07:01:06] DEBUG[26832] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer [Jan 31 07:01:06] DEBUG[26832] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer [Jan 31 07:01:06] DEBUG[26832] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:06] DEBUG[26832] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0 [Jan 31 07:01:06] VERBOSE[26832] logger.c: == Manager 'admin' logged on from 127.0.0.1 [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:9] Set("SIP/112233-06f73180", "__agent_auto_pause=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '2' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:10] Set("SIP/112233-06f73180", "__workgroup_auto_pause=2") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:11] Set("SIP/112233-06f73180", "__caller=112233") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/receiver' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/receiver not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:12] Set("SIP/112233-06f73180", "__receiver=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/A_extension' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/A_extension not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:13] Set("SIP/112233-06f73180", "__A_extension=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/A_agent' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/A_agent not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:14] Set("SIP/112233-06f73180", "__A_agent=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '22901' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:15] Set("SIP/112233-06f73180", "__B_extension=22901") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '22901' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:16] Set("SIP/112233-06f73180", "__B_agent=22901") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '2943' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:17] Set("SIP/112233-06f73180", "__dnis=2943") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '1' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:18] Set("SIP/112233-06f73180", "__dnis_written=1") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/transfer_back' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/transfer_back not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:19] Set("SIP/112233-06f73180", "__transfer_back=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '3' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:20] Set("SIP/112233-06f73180", "__queue_call_num=3") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is 'external' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:21] Set("SIP/112233-06f73180", "__source_type=external") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:22] Set("SIP/112233-06f73180", "__source_num=112233") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/source_num_id' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/source_num_id not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:23] Set("SIP/112233-06f73180", "__source_num_id=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '8006772943' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:24] Set("SIP/112233-06f73180", "__source_ext=8006772943") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '70' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:25] Set("SIP/112233-06f73180", "__source_ext_id=70") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '1' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:26] Set("SIP/112233-06f73180", "__source_dpt_id=1") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/middle_type' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/middle_type not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:27] Set("SIP/112233-06f73180", "__middle_type=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/middle_num' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/middle_num not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:28] Set("SIP/112233-06f73180", "__middle_num=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/middle_num_id' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/middle_num_id not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:29] Set("SIP/112233-06f73180", "__middle_num_id=") in new stack [Jan 31 07:01:06] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:06] DEBUG[26704] db.c: Unable to find key '1201791524.235/middle_ext' in family 'call_globals' [Jan 31 07:01:06] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/middle_ext not found in database. [Jan 31 07:01:06] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:06] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:06] DEBUG[26832] manager.c: Manager received command 'Command' [Jan 31 07:01:07] DEBUG[26832] manager.c: Manager received command 'QueueAdd' [Jan 31 07:01:07] DEBUG[26832] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:07] DEBUG[26832] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_table WHERE name = '22901' [Jan 31 07:01:07] DEBUG[26832] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:07] DEBUG[26832] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_member_table WHERE interface LIKE '%' AND queue_name = '22901' ORDER BY interface [Jan 31 07:01:07] DEBUG[26832] app_queue.c: Adding Agent/22243 to the list of interfaces that make up all of our queue members. [Jan 31 07:01:07] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:07] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:07] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:08] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:08] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:08] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:08] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:09] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:09] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:09] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:09] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:10] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:10] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:10] DEBUG[26753] app_queue.c: It's our turn (SIP/112233-0746d320). [Jan 31 07:01:10] DEBUG[26753] app_queue.c: SIP/112233-0746d320 is trying to call a queue member. [Jan 31 07:01:10] DEBUG[26753] app_queue.c: Trying 'Agent/22206' with metric 998888 [Jan 31 07:01:10] DEBUG[26753] app_queue.c: Agent/22206 paused, can't receive call [Jan 31 07:01:10] DEBUG[26753] app_queue.c: Trying 'Agent/22243' with metric 5000000 [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable MACRO_DEPTH. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_ext. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_ext_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_num_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable xfer_block_started. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable queue_call_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable call_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable DB_RESULT. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable number. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable agent_count_2. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_dpt_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable workgroup_auto_pause. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable queue_ring_time. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable directly_from_queue. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable call_from_queue. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable SYSTEMSTATUS. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable MYSQL_STATUS. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable B_extension. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_num_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable have_mapping. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable result1. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable extension_callable. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable ring_time. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable pause_on_direct_call. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable pause_on_wg_call. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable dpt_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable extension_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable extension_type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable connid. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable B_agent. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_ext. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_ext_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_num_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable cdr_block_started. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_ext. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_ext_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_num_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable dnis_written. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable business_hours. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable dnis_mode. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable agent_count_1. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable QUEUE_PRIO. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable route_enabled. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable INVALID_EXTEN. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable source_ext_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable source_ext. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable source_dpt_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable dnis. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable ~GOSUB~STACK~. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable i. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable source_num. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable source_type. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable initialized. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable hangup_callback. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable agent_call_counter_set. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable transfer_back. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable transfer_count. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable caller. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable parent_channel. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable call_id. [Jan 31 07:01:10] DEBUG[26753] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable SIPCALLID. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable SIPUSERAGENT. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable SIPDOMAIN. [Jan 31 07:01:10] DEBUG[26753] channel.c: Not copying variable SIPURI. [Jan 31 07:01:10] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:11] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:11] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:11] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:12] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:12] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:12] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:12] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:06] DEBUG[26835] pbx.c: Launching 'NoOp' [Jan 31 07:01:06] DEBUG[24762] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:13] NOTICE[24762] chan_iax2.c: Restricting registration for peer 'iaxmodem4' to 60 seconds (requested 300) [Jan 31 07:01:13] DEBUG[24762] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 13) [Jan 31 07:01:13] DEBUG[24762] chan_iax2.c: Acking anyway [Jan 31 07:01:13] DEBUG[24762] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 13) [Jan 31 07:01:13] DEBUG[24762] chan_iax2.c: Acking anyway [Jan 31 07:01:13] DEBUG[24768] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:13] NOTICE[24768] chan_iax2.c: Restricting registration for peer 'iaxmodem1' to 60 seconds (requested 300) [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:30] Set("SIP/112233-06f73180", "__middle_ext=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] db.c: Unable to find key '1201791524.235/middle_ext_id' in family 'call_globals' [Jan 31 07:01:13] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/middle_ext_id not found in database. [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:31] Set("SIP/112233-06f73180", "__middle_ext_id=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] db.c: Unable to find key '1201791524.235/middle_dpt_id' in family 'call_globals' [Jan 31 07:01:13] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/middle_dpt_id not found in database. [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:32] Set("SIP/112233-06f73180", "__middle_dpt_id=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is 'queue' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:33] Set("SIP/112233-06f73180", "__target_type=queue") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '22901' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:34] Set("SIP/112233-06f73180", "__target_num=22901") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '84' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:35] Set("SIP/112233-06f73180", "__target_num_id=84") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] db.c: Unable to find key '1201791524.235/target_ext' in family 'call_globals' [Jan 31 07:01:13] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/target_ext not found in database. [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:36] Set("SIP/112233-06f73180", "__target_ext=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] db.c: Unable to find key '1201791524.235/target_ext_id' in family 'call_globals' [Jan 31 07:01:13] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/target_ext_id not found in database. [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:37] Set("SIP/112233-06f73180", "__target_ext_id=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '1' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:38] Set("SIP/112233-06f73180", "__target_dpt_id=1") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '3' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:39] Set("SIP/112233-06f73180", "last_call_num=3") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:40] GotoIf("SIP/112233-06f73180", "0?41:42") in new stack [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,42) [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:42] NoOp("SIP/112233-06f73180", "Finish if-read_vars-35") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:13] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:43] Set("SIP/112233-06f73180", "i=1") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("SIP/112233-06f73180", "1?45:53") in new stack [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:45] Set("SIP/112233-06f73180", "__target_1_type=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:46] Set("SIP/112233-06f73180", "__target_1_num=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:47] Set("SIP/112233-06f73180", "__target_1_num_id=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:48] Set("SIP/112233-06f73180", "__target_1_ext=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:49] Set("SIP/112233-06f73180", "__target_1_ext_id=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:13] DEBUG[26704] db.c: Unable to find key '1201791524.235/target_1_disposition' in family 'call_globals' [Jan 31 07:01:13] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/target_1_disposition not found in database. [Jan 31 07:01:13] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:13] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:13] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:50] Set("SIP/112233-06f73180", "__target_1_disposition=") in new stack [Jan 31 07:01:13] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:14] DEBUG[26704] pbx.c: Expression result is '2' [Jan 31 07:01:14] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:14] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:51] Set("SIP/112233-06f73180", "i=2") in new stack [Jan 31 07:01:14] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:14] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:14] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:52] Goto("SIP/112233-06f73180", "44") in new stack [Jan 31 07:01:14] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:01:14] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:14] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:14] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:14] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:15] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("SIP/112233-06f73180", "1?45:53") in new stack [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:45] Set("SIP/112233-06f73180", "__target_2_type=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '462' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:46] Set("SIP/112233-06f73180", "__target_2_num=462") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '462' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:47] Set("SIP/112233-06f73180", "__target_2_num_id=462") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:48] Set("SIP/112233-06f73180", "__target_2_ext=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:49] Set("SIP/112233-06f73180", "__target_2_ext_id=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] db.c: Unable to find key '1201791524.235/target_2_disposition' in family 'call_globals' [Jan 31 07:01:15] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/target_2_disposition not found in database. [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:50] Set("SIP/112233-06f73180", "__target_2_disposition=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Expression result is '3' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:51] Set("SIP/112233-06f73180", "i=3") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:52] Goto("SIP/112233-06f73180", "44") in new stack [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:15] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("SIP/112233-06f73180", "1?45:53") in new stack [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is 'queue' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:45] Set("SIP/112233-06f73180", "__target_3_type=queue") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '22901' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:46] Set("SIP/112233-06f73180", "__target_3_num=22901") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '84' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:47] Set("SIP/112233-06f73180", "__target_3_num_id=84") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:48] Set("SIP/112233-06f73180", "__target_3_ext=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:49] Set("SIP/112233-06f73180", "__target_3_ext_id=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] db.c: Unable to find key '1201791524.235/target_3_disposition' in family 'call_globals' [Jan 31 07:01:15] DEBUG[26704] func_db.c: DB: call_globals/1201791524.235/target_3_disposition not found in database. [Jan 31 07:01:15] DEBUG[26704] pbx.c: Function result is '' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:50] Set("SIP/112233-06f73180", "__target_3_disposition=") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Expression result is '4' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:51] Set("SIP/112233-06f73180", "i=4") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:52] Goto("SIP/112233-06f73180", "44") in new stack [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:15] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("SIP/112233-06f73180", "0?45:53") in new stack [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,53) [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:53] NoOp("SIP/112233-06f73180", "Finish for-read_vars-36") in new stack [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:15] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:54] GotoIf("SIP/112233-06f73180", "1?55:56") in new stack [Jan 31 07:01:15] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,55) [Jan 31 07:01:15] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:15] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:16] ERROR[26784] /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 07:01:16] ERROR[26784] /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 07:01:16] ERROR[26765] /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 07:01:16] ERROR[26765] /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 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:55] Set("SIP/112233-06f73180", "__transfer_count=0") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:56] NoOp("SIP/112233-06f73180", "Finish if-read_vars-37") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:16] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:57] GotoIf("SIP/112233-06f73180", "1?58:59") in new stack [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,58) [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:58] Set("SIP/112233-06f73180", "__transfer_back=0") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:59] NoOp("SIP/112233-06f73180", "Finish if-read_vars-38") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:16] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:60] GotoIf("SIP/112233-06f73180", "1?61:62") in new stack [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,61) [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:61] Set("SIP/112233-06f73180", "__agent_call_counter_set=0") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:62] NoOp("SIP/112233-06f73180", "Finish if-read_vars-39") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:16] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:63] GotoIf("SIP/112233-06f73180", "0?64:65") in new stack [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,65) [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:65] NoOp("SIP/112233-06f73180", "Finish if-read_vars-40") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:16] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:66] GotoIf("SIP/112233-06f73180", "0?67:68") in new stack [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,68) [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:68] NoOp("SIP/112233-06f73180", "Finish if-read_vars-41") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:16] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:69] GotoIf("SIP/112233-06f73180", "0?70:71") in new stack [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Goto (macro-read_vars,s,71) [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:71] NoOp("SIP/112233-06f73180", "Finish if-read_vars-42") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-read_vars:72] NoOp("SIP/112233-06f73180", "-(E)------------------------------------- macro read_vars -----------") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'Macro' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [17@default-queue:5] Macro("SIP/112233-06f73180", "dumpvars") in new stack [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:1] NoOp("SIP/112233-06f73180", "-(B)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:16] DEBUG[26704] pbx.c: Function result is 'ITN Economy Sales-----22901-----112233' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:2] NoOp("SIP/112233-06f73180", "CALLERIDNAME(CALLERIDNUM)[CALLINGPRES]=ITN Economy Sales-----22901-----112233(112233)[0]") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:3] NoOp("SIP/112233-06f73180", "DIALEDPEERNAME(DIALEDPEERNUMBER)[DIALEDTIME]DIALSTATUS=()[]") in new stack [Jan 31 07:01:16] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:16] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:16] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:17] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:17] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:4] NoOp("SIP/112233-06f73180", "ANSWEREDTIME(UNIQUEID)PRIORITY=(1201791524.235)4 ### [HANGUPCAUSE]MEETMESECS=[0]") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:5] NoOp("SIP/112233-06f73180", "SIPDOMAIN=81.198.164.117 ### SIP_CODEC= ### SIPCALLID=3284f62c364deffe0a40bdb23071eadb@81.198.164.48") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:6] NoOp("SIP/112233-06f73180", "TRANSFER_CONTEXT=transfer ### TXTCIDNAME= ### BLINDTRANSFER= ### TRANSFERSTATUS=") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:7] NoOp("SIP/112233-06f73180", "TOUCH_MONITOR= ### CHANNEL=SIP/112233-06f73180") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:8] NoOp("SIP/112233-06f73180", "MACRO_CONTEXT=default-queue ### MACRO_EXTEN=17 ### MACRO_PRIORITY=5") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:9] NoOp("SIP/112233-06f73180", "----------------- User variables ---------------") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:10] NoOp("SIP/112233-06f73180", "dnis=2943 agent(extension) A[()] -> B[22901(22901)]") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:11] NoOp("SIP/112233-06f73180", "business_hours=yes ### agent_auto_pause= ### workgroup_auto_pause=2 ### queue_ring_time=150") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:12] NoOp("SIP/112233-06f73180", "call_id-call_num=1201791524.235-3") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:13] NoOp("SIP/112233-06f73180", "call_from_queue=22901 ### direct_from_queue= ### queue_call= ### queue_call_num=3") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:14] NoOp("SIP/112233-06f73180", "transfer_count=0 ### transfer_to_agent= ### transfer_back=0 ### agent_call_counter_set=0") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:15] NoOp("SIP/112233-06f73180", "cdr_block_started=1") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:16] NoOp("SIP/112233-06f73180", "is_agent= ### have_mapping=0 ### agent_away=") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:17] NoOp("SIP/112233-06f73180", "source_type=external ### source_num=112233 ### source_num_id= ### source_ext=8006772943 ### source_ext_id=70 ### source_dpt_id=1") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:18] NoOp("SIP/112233-06f73180", "middle_type= ### middle_num= ### middle_num_id= ### middle_ext= ### middle_ext_id= ### middle_dpt_id=") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:19] NoOp("SIP/112233-06f73180", "target_type=queue ### target_num=22901 ### target_num_id=84 ### target_ext= ### target_ext_id= ### target_dpt_id=1") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:20] NoOp("SIP/112233-06f73180", "parent_channel=#SIP/112233-06f73180") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:17] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:17] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:21] Set("SIP/112233-06f73180", "i=1") in new stack [Jan 31 07:01:17] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:17] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:17] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:17] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:17] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "1?23:26") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/112233-06f73180", "target[1]=|||||") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:18] DEBUG[26704] pbx.c: Expression result is '2' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:24] Set("SIP/112233-06f73180", "i=2") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:25] Goto("SIP/112233-06f73180", "22") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:18] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "1?23:26") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/112233-06f73180", "target[2]=|462|462|||") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:18] DEBUG[26704] pbx.c: Expression result is '3' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:24] Set("SIP/112233-06f73180", "i=3") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:25] Goto("SIP/112233-06f73180", "22") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:18] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "1?23:26") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/112233-06f73180", "target[3]=queue|22901|84|||") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:18] DEBUG[26704] pbx.c: Expression result is '4' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:24] Set("SIP/112233-06f73180", "i=4") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:25] Goto("SIP/112233-06f73180", "22") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:18] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "0?23:26") in new stack [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,26) [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:26] NoOp("SIP/112233-06f73180", "Finish for-dumpvars-1") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:27] NoOp("SIP/112233-06f73180", "v_data=") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:28] NoOp("SIP/112233-06f73180", "-(E)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:01:18] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:18] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [17@default-queue:6] Set("SIP/112233-06f73180", "__A_extension=112233") in new stack [Jan 31 07:01:18] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:18] VERBOSE[26704] logger.c: -- Executing [17@default-queue:7] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/A_extension)=112233") in new stack [Jan 31 07:01:18] VERBOSE[26835] logger.c: -- Executing [2943@default-external:1] NoOp("SIP/112233-06f611d0", "-(B)------------------------------------- context default-external -----------") in new stack [Jan 31 07:01:18] DEBUG[26835] pbx.c: Launching 'NoOp' [Jan 31 07:01:18] VERBOSE[26835] logger.c: -- Executing [2943@default-external:2] NoOp("SIP/112233-06f611d0", "---------- External call arrived ----------") in new stack [Jan 31 07:01:18] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:18] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [17@default-queue:8] Set("SIP/112233-06f73180", "__A_agent=112233") in new stack [Jan 31 07:01:19] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [17@default-queue:9] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/A_agent)=112233") in new stack [Jan 31 07:01:19] VERBOSE[26832] logger.c: == Manager 'admin' logged off from 127.0.0.1 [Jan 31 07:01:19] VERBOSE[26753] logger.c: -- outgoing agentcall, to agent '22243', on 'Local/22243@default-queue-4675,1' [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_ext. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_ext_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_num. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_num_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_3_type. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable xfer_block_started. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable queue_call_num. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_dpt_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_type. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable workgroup_auto_pause. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable queue_ring_time. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable directly_from_queue. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable call_from_queue. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable B_extension. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_num_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_num. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable B_agent. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_ext. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_ext_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_num. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_num_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_2_type. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable cdr_block_started. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_ext. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_ext_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_num. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_num_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable target_1_type. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable dnis_written. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable business_hours. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable route_enabled. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable source_ext_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable source_ext. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable source_dpt_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable dnis. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable source_num. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable source_type. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable hangup_callback. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable agent_call_counter_set. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable transfer_back. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable transfer_count. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable caller. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable parent_channel. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable call_id. [Jan 31 07:01:19] DEBUG[26753] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [17@default-queue:10] Set("SIP/112233-06f73180", "__queue_call=1") in new stack [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'Macro' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [17@default-queue:11] Macro("SIP/112233-06f73180", "dumpvars") in new stack [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:1] NoOp("SIP/112233-06f73180", "-(B)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Function result is 'ITN Economy Sales-----22901-----112233' [Jan 31 07:01:19] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:2] NoOp("SIP/112233-06f73180", "CALLERIDNAME(CALLERIDNUM)[CALLINGPRES]=ITN Economy Sales-----22901-----112233(112233)[0]") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:3] NoOp("SIP/112233-06f73180", "DIALEDPEERNAME(DIALEDPEERNUMBER)[DIALEDTIME]DIALSTATUS=()[]") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:4] NoOp("SIP/112233-06f73180", "ANSWEREDTIME(UNIQUEID)PRIORITY=(1201791524.235)4 ### [HANGUPCAUSE]MEETMESECS=[0]") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:5] NoOp("SIP/112233-06f73180", "SIPDOMAIN=81.198.164.117 ### SIP_CODEC= ### SIPCALLID=3284f62c364deffe0a40bdb23071eadb@81.198.164.48") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:6] NoOp("SIP/112233-06f73180", "TRANSFER_CONTEXT=transfer ### TXTCIDNAME= ### BLINDTRANSFER= ### TRANSFERSTATUS=") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:7] NoOp("SIP/112233-06f73180", "TOUCH_MONITOR= ### CHANNEL=SIP/112233-06f73180") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:8] NoOp("SIP/112233-06f73180", "MACRO_CONTEXT=default-queue ### MACRO_EXTEN=17 ### MACRO_PRIORITY=11") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: Noop [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:9] NoOp("SIP/112233-06f73180", "----------------- User variables ---------------") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:10] NoOp("SIP/112233-06f73180", "dnis=2943 agent(extension) A[112233(112233)] -> B[22901(22901)]") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:11] NoOp("SIP/112233-06f73180", "business_hours=yes ### agent_auto_pause= ### workgroup_auto_pause=2 ### queue_ring_time=150") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:12] NoOp("SIP/112233-06f73180", "call_id-call_num=1201791524.235-3") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:13] NoOp("SIP/112233-06f73180", "call_from_queue=22901 ### direct_from_queue= ### queue_call=1 ### queue_call_num=3") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:14] NoOp("SIP/112233-06f73180", "transfer_count=0 ### transfer_to_agent= ### transfer_back=0 ### agent_call_counter_set=0") in new stack [Jan 31 07:01:19] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:19] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:19] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:20] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:15] NoOp("SIP/112233-06f73180", "cdr_block_started=1") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:16] NoOp("SIP/112233-06f73180", "is_agent= ### have_mapping=0 ### agent_away=") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:17] NoOp("SIP/112233-06f73180", "source_type=external ### source_num=112233 ### source_num_id= ### source_ext=8006772943 ### source_ext_id=70 ### source_dpt_id=1") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:18] NoOp("SIP/112233-06f73180", "middle_type= ### middle_num= ### middle_num_id= ### middle_ext= ### middle_ext_id= ### middle_dpt_id=") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:19] NoOp("SIP/112233-06f73180", "target_type=queue ### target_num=22901 ### target_num_id=84 ### target_ext= ### target_ext_id= ### target_dpt_id=1") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:20] NoOp("SIP/112233-06f73180", "parent_channel=#SIP/112233-06f73180") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:21] Set("SIP/112233-06f73180", "i=1") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "1?23:26") in new stack [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/112233-06f73180", "target[1]=|||||") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '2' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:24] Set("SIP/112233-06f73180", "i=2") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:25] Goto("SIP/112233-06f73180", "22") in new stack [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "1?23:26") in new stack [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/112233-06f73180", "target[2]=|462|462|||") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '3' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:24] Set("SIP/112233-06f73180", "i=3") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:25] Goto("SIP/112233-06f73180", "22") in new stack [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "1?23:26") in new stack [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/112233-06f73180", "target[3]=queue|22901|84|||") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '4' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:24] Set("SIP/112233-06f73180", "i=4") in new stack [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Set [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:25] Goto("SIP/112233-06f73180", "22") in new stack [Jan 31 07:01:20] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:01:20] DEBUG[26704] app_macro.c: Executed application: Goto [Jan 31 07:01:20] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:01:20] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:01:21] ERROR[26765] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 10 sec for mutex '&q->lock'? [Jan 31 07:01:21] ERROR[26765] /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 07:01:21] ERROR[26784] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 10 sec for mutex '&q->lock'? [Jan 31 07:01:21] ERROR[26784] /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 07:01:21] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("SIP/112233-06f73180", "0?23:26") in new stack [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Goto (macro-dumpvars,s,26) [Jan 31 07:01:21] DEBUG[26704] app_macro.c: Executed application: GotoIf [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:26] NoOp("SIP/112233-06f73180", "Finish for-dumpvars-1") in new stack [Jan 31 07:01:21] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:27] NoOp("SIP/112233-06f73180", "v_data=") in new stack [Jan 31 07:01:21] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [s@macro-dumpvars:28] NoOp("SIP/112233-06f73180", "-(E)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:01:21] DEBUG[26704] app_macro.c: Executed application: NoOp [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [17@default-queue:12] Set("SIP/112233-06f73180", "__TRANSFER_CONTEXT=transfer") in new stack [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [17@default-queue:13] Set("SIP/112233-06f73180", "__prev_receiver=") in new stack [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [17@default-queue:14] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/prev_receiver)=") in new stack [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [17@default-queue:15] Set("SIP/112233-06f73180", "__receiver=17") in new stack [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [17@default-queue:16] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/receiver)=17") in new stack [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:1] NoOp("Local/22243@default-queue-4675,2", "-(B)------------------------------------- context default-queue ---------------") in new stack [Jan 31 07:01:21] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:2] NoOp("Local/22243@default-queue-4675,2", "---- Initiated queue call to 22243 from 112233----") in new stack [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'Macro' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:3] Macro("Local/22243@default-queue-4675,2", "init_channel") in new stack [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:1] NoOp("Local/22243@default-queue-4675,2", "-(B)------------------------------------- macro init_channel (Local/22243@default-queue-4675,2) -----------") in new stack [Jan 31 07:01:21] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:2] Set("Local/22243@default-queue-4675,2", "__TRANSFER_CONTEXT="transfer"") in new stack [Jan 31 07:01:21] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:21] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:3] GotoIf("Local/22243@default-queue-4675,2", "0?4:7") in new stack [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,7) [Jan 31 07:01:21] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:7] NoOp("Local/22243@default-queue-4675,2", "Call id already set to 1201791594.239") in new stack [Jan 31 07:01:21] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:8] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-21") in new stack [Jan 31 07:01:21] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:21] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:9] GotoIf("Local/22243@default-queue-4675,2", "1?10:11") in new stack [Jan 31 07:01:21] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,10) [Jan 31 07:01:21] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] VERBOSE[26704] logger.c: -- Executing [17@default-queue:17] Set("SIP/112233-06f73180", "__target_num=17") in new stack [Jan 31 07:01:21] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:21] DEBUG[26838] pbx.c: Function result is '3' [Jan 31 07:01:21] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:22] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:22] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:22] VERBOSE[26704] logger.c: -- Executing [17@default-queue:18] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/target_num)=17") in new stack [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:10] Set("Local/22243@default-queue-4675,2", "call_num=3") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:11] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-22") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:22] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:12] GotoIf("Local/22243@default-queue-4675,2", "0?13:14") in new stack [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,14) [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:14] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-23") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:22] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:15] GotoIf("Local/22243@default-queue-4675,2", "1?16:22") in new stack [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,16) [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:22] DEBUG[26838] pbx.c: Expression result is '4' [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:16] Set("Local/22243@default-queue-4675,2", "call_num=4") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:17] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/call_num)=4") in new stack [Jan 31 07:01:22] DEBUG[26704] pbx.c: Launching 'Goto' [Jan 31 07:01:22] VERBOSE[26704] logger.c: -- Executing [17@default-queue:19] Goto("SIP/112233-06f73180", "local_dial|17|1") in new stack [Jan 31 07:01:22] VERBOSE[26704] logger.c: -- Goto (local_dial,17,1) [Jan 31 07:01:22] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26704] logger.c: -- Executing [17@local_dial:1] Set("SIP/112233-06f73180", "__B_agent=17") in new stack [Jan 31 07:01:22] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26704] logger.c: -- Executing [17@local_dial:2] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/B_agent)=17") in new stack [Jan 31 07:01:22] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:01:22] VERBOSE[26704] logger.c: -- Executing [17@local_dial:3] MYSQL("SIP/112233-06f73180", "Connect connid localhost asterisk AstStgPw09 asterisk") in new stack [Jan 31 07:01:22] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:18] NoOp("Local/22243@default-queue-4675,2", "call_num=4") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:22] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:19] Set("Local/22243@default-queue-4675,2", "CDR(userfield)=#call_id=1201791594.239-4") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:20] Set("Local/22243@default-queue-4675,2", "CDR(accountcode)=1201791594.239") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:21] Set("Local/22243@default-queue-4675,2", "__parent_channel=#SIP/112233-0746d320#Local/22243@default-queue-4675,2") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:22] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-24") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:22] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:23] GotoIf("Local/22243@default-queue-4675,2", "0?24:26") in new stack [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,26) [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:22] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:26] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-25") in new stack [Jan 31 07:01:22] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:22] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:22] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:22] DEBUG[24763] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:22] NOTICE[24763] chan_iax2.c: Restricting registration for peer 'iaxmodem5' to 60 seconds (requested 300) [Jan 31 07:01:22] DEBUG[24760] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:22] NOTICE[24760] chan_iax2.c: Restricting registration for peer 'iaxmodem2' to 60 seconds (requested 300) [Jan 31 07:01:22] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:23] ERROR[26835] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: pbx.c line 1150 (pbx_retrieve_variable): Deadlock? waited 5 sec for mutex '&c->lock'? [Jan 31 07:01:23] ERROR[26835] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_sip.c line 13903 (handle_request_invite): '&c->lock' was locked here. [Jan 31 07:01:24] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:25] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:26] ERROR[26765] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 15 sec for mutex '&q->lock'? [Jan 31 07:01:26] ERROR[26765] /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 07:01:26] ERROR[26784] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 15 sec for mutex '&q->lock'? [Jan 31 07:01:26] ERROR[26784] /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 07:01:26] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:26] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:27] GotoIf("Local/22243@default-queue-4675,2", "0?28:29") in new stack [Jan 31 07:01:26] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,29) [Jan 31 07:01:26] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:26] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:26] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:29] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-26") in new stack [Jan 31 07:01:26] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:26] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:26] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:26] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:30] GotoIf("Local/22243@default-queue-4675,2", "0?31:32") in new stack [Jan 31 07:01:26] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,32) [Jan 31 07:01:26] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:26] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:26] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:32] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-27") in new stack [Jan 31 07:01:26] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:27] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:33] GotoIf("Local/22243@default-queue-4675,2", "0?34:35") in new stack [Jan 31 07:01:27] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,35) [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:35] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-28") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:27] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:36] GotoIf("Local/22243@default-queue-4675,2", "0?37:38") in new stack [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,38) [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:38] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-29") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:27] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:39] GotoIf("Local/22243@default-queue-4675,2", "0?40:41") in new stack [Jan 31 07:01:27] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,41) [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:41] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-30") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:27] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:42] GotoIf("Local/22243@default-queue-4675,2", "0?43:44") in new stack [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Goto (macro-init_channel,s,44) [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:27] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:44] NoOp("Local/22243@default-queue-4675,2", "Finish if-init_channel-31") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:45] Set("Local/22243@default-queue-4675,2", "initialized=1") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-init_channel:46] NoOp("Local/22243@default-queue-4675,2", "-(E)------------------------------------- macro init_channel -----------") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'Macro' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:4] Macro("Local/22243@default-queue-4675,2", "read_vars") in new stack [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:27] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:1] NoOp("Local/22243@default-queue-4675,2", "-(B)------------------------------------- macro read_vars (Local/22243@default-queue-4675,2) -----------") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:01:27] DEBUG[26838] db.c: Unable to find key '1201791594.239/transfer_count' in family 'call_globals' [Jan 31 07:01:27] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/transfer_count not found in database. [Jan 31 07:01:27] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:27] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:27] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:2] Set("Local/22243@default-queue-4675,2", "__transfer_count=") in new stack [Jan 31 07:01:27] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:27] DEBUG[26838] db.c: Unable to find key '1201791594.239/agent_call_counter_set' in family 'call_globals' [Jan 31 07:01:27] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/agent_call_counter_set not found in database. [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] ERROR[26835] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: pbx.c line 1150 (pbx_retrieve_variable): Deadlock? waited 10 sec for mutex '&c->lock'? [Jan 31 07:01:28] ERROR[26835] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_sip.c line 13903 (handle_request_invite): '&c->lock' was locked here. [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:3] Set("Local/22243@default-queue-4675,2", "__agent_call_counter_set=") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '22901' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:4] Set("Local/22243@default-queue-4675,2", "__call_from_queue=22901") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '22901' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:5] Set("Local/22243@default-queue-4675,2", "__directly_from_queue=22901") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '1' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:6] Set("Local/22243@default-queue-4675,2", "__cdr_block_started=1") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:7] Set("Local/22243@default-queue-4675,2", "__xfer_block_started=") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is 'yes' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:8] Set("Local/22243@default-queue-4675,2", "__business_hours=yes") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] db.c: Unable to find key '1201791594.239/agent_auto_pause' in family 'call_globals' [Jan 31 07:01:28] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/agent_auto_pause not found in database. [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:9] Set("Local/22243@default-queue-4675,2", "__agent_auto_pause=") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '2' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:10] Set("Local/22243@default-queue-4675,2", "__workgroup_auto_pause=2") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:11] Set("Local/22243@default-queue-4675,2", "__caller=112233") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] db.c: Unable to find key '1201791594.239/receiver' in family 'call_globals' [Jan 31 07:01:28] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/receiver not found in database. [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:12] Set("Local/22243@default-queue-4675,2", "__receiver=") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] db.c: Unable to find key '1201791594.239/A_extension' in family 'call_globals' [Jan 31 07:01:28] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/A_extension not found in database. [Jan 31 07:01:28] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:28] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:28] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:13] Set("Local/22243@default-queue-4675,2", "__A_extension=") in new stack [Jan 31 07:01:28] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:28] DEBUG[26838] db.c: Unable to find key '1201791594.239/A_agent' in family 'call_globals' [Jan 31 07:01:29] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/A_agent not found in database. [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:14] Set("Local/22243@default-queue-4675,2", "__A_agent=") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '22901' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:15] Set("Local/22243@default-queue-4675,2", "__B_extension=22901") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '22901' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:16] Set("Local/22243@default-queue-4675,2", "__B_agent=22901") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '2943' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:17] Set("Local/22243@default-queue-4675,2", "__dnis=2943") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '1' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:18] Set("Local/22243@default-queue-4675,2", "__dnis_written=1") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] db.c: Unable to find key '1201791594.239/transfer_back' in family 'call_globals' [Jan 31 07:01:29] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/transfer_back not found in database. [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:19] Set("Local/22243@default-queue-4675,2", "__transfer_back=") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '3' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:20] Set("Local/22243@default-queue-4675,2", "__queue_call_num=3") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is 'external' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:21] Set("Local/22243@default-queue-4675,2", "__source_type=external") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:22] Set("Local/22243@default-queue-4675,2", "__source_num=112233") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] db.c: Unable to find key '1201791594.239/source_num_id' in family 'call_globals' [Jan 31 07:01:29] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/source_num_id not found in database. [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:23] Set("Local/22243@default-queue-4675,2", "__source_num_id=") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '8006772943' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:24] Set("Local/22243@default-queue-4675,2", "__source_ext=8006772943") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:29] DEBUG[26838] pbx.c: Function result is '70' [Jan 31 07:01:29] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:29] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:25] Set("Local/22243@default-queue-4675,2", "__source_ext_id=70") in new stack [Jan 31 07:01:29] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '1' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:26] Set("Local/22243@default-queue-4675,2", "__source_dpt_id=1") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/middle_type' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/middle_type not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:27] Set("Local/22243@default-queue-4675,2", "__middle_type=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/middle_num' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/middle_num not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:28] Set("Local/22243@default-queue-4675,2", "__middle_num=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/middle_num_id' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/middle_num_id not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:29] Set("Local/22243@default-queue-4675,2", "__middle_num_id=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/middle_ext' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/middle_ext not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:30] Set("Local/22243@default-queue-4675,2", "__middle_ext=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/middle_ext_id' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/middle_ext_id not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:31] Set("Local/22243@default-queue-4675,2", "__middle_ext_id=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/middle_dpt_id' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/middle_dpt_id not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:32] Set("Local/22243@default-queue-4675,2", "__middle_dpt_id=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is 'queue' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:33] Set("Local/22243@default-queue-4675,2", "__target_type=queue") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '22901' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:34] Set("Local/22243@default-queue-4675,2", "__target_num=22901") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '84' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:35] Set("Local/22243@default-queue-4675,2", "__target_num_id=84") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_ext' in family 'call_globals' [Jan 31 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_ext not found in database. [Jan 31 07:01:30] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:30] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:30] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:36] Set("Local/22243@default-queue-4675,2", "__target_ext=") in new stack [Jan 31 07:01:30] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:30] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_ext_id' in family 'call_globals' [Jan 31 07:01:31] ERROR[26784] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 20 sec for mutex '&q->lock'? [Jan 31 07:01:31] ERROR[26784] /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 07:01:31] ERROR[26765] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: app_queue.c line 523 (get_member_status): Deadlock? waited 20 sec for mutex '&q->lock'? [Jan 31 07:01:31] ERROR[26765] /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 07:01:30] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_ext_id not found in database. [Jan 31 07:01:31] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:37] Set("Local/22243@default-queue-4675,2", "__target_ext_id=") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:31] DEBUG[26838] pbx.c: Function result is '1' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:38] Set("Local/22243@default-queue-4675,2", "__target_dpt_id=1") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:31] DEBUG[26838] pbx.c: Function result is '4' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:39] Set("Local/22243@default-queue-4675,2", "last_call_num=4") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:31] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:31] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:40] GotoIf("Local/22243@default-queue-4675,2", "0?41:42") in new stack [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,42) [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:42] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-35") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:01:31] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:43] Set("Local/22243@default-queue-4675,2", "i=1") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:31] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("Local/22243@default-queue-4675,2", "1?45:53") in new stack [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:31] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:45] Set("Local/22243@default-queue-4675,2", "__target_1_type=") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:31] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:31] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:31] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:46] Set("Local/22243@default-queue-4675,2", "__target_1_num=") in new stack [Jan 31 07:01:31] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:47] Set("Local/22243@default-queue-4675,2", "__target_1_num_id=") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:48] Set("Local/22243@default-queue-4675,2", "__target_1_ext=") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:49] Set("Local/22243@default-queue-4675,2", "__target_1_ext_id=") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_1_disposition' in family 'call_globals' [Jan 31 07:01:32] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_1_disposition not found in database. [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:50] Set("Local/22243@default-queue-4675,2", "__target_1_disposition=") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Expression result is '2' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:51] Set("Local/22243@default-queue-4675,2", "i=2") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:52] Goto("Local/22243@default-queue-4675,2", "44") in new stack [Jan 31 07:01:32] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:01:32] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("Local/22243@default-queue-4675,2", "1?45:53") in new stack [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:45] Set("Local/22243@default-queue-4675,2", "__target_2_type=") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '462' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:46] Set("Local/22243@default-queue-4675,2", "__target_2_num=462") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '462' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:47] Set("Local/22243@default-queue-4675,2", "__target_2_num_id=462") in new stack [Jan 31 07:01:32] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:32] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:32] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:32] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:48] Set("Local/22243@default-queue-4675,2", "__target_2_ext=") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] ERROR[26835] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: pbx.c line 1150 (pbx_retrieve_variable): Deadlock? waited 15 sec for mutex '&c->lock'? [Jan 31 07:01:33] ERROR[26835] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_sip.c line 13903 (handle_request_invite): '&c->lock' was locked here. [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:49] Set("Local/22243@default-queue-4675,2", "__target_2_ext_id=") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_2_disposition' in family 'call_globals' [Jan 31 07:01:33] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_2_disposition not found in database. [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:50] Set("Local/22243@default-queue-4675,2", "__target_2_disposition=") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Expression result is '3' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:51] Set("Local/22243@default-queue-4675,2", "i=3") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:52] Goto("Local/22243@default-queue-4675,2", "44") in new stack [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:01:33] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("Local/22243@default-queue-4675,2", "1?45:53") in new stack [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is 'queue' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:45] Set("Local/22243@default-queue-4675,2", "__target_3_type=queue") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is '22901' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:46] Set("Local/22243@default-queue-4675,2", "__target_3_num=22901") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is '84' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:47] Set("Local/22243@default-queue-4675,2", "__target_3_num_id=84") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:48] Set("Local/22243@default-queue-4675,2", "__target_3_ext=") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:33] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:33] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:49] Set("Local/22243@default-queue-4675,2", "__target_3_ext_id=") in new stack [Jan 31 07:01:33] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:33] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_3_disposition' in family 'call_globals' [Jan 31 07:01:34] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_3_disposition not found in database. [Jan 31 07:01:34] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:01:34] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:34] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:50] Set("Local/22243@default-queue-4675,2", "__target_3_disposition=") in new stack [Jan 31 07:01:34] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:34] DEBUG[26838] pbx.c: Expression result is '4' [Jan 31 07:01:34] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:01:34] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:51] Set("Local/22243@default-queue-4675,2", "i=4") in new stack [Jan 31 07:01:34] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:01:34] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:01:34] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: chan_sip: ast_sched_runq ran 28 all at once [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 7ca944e203334b5e1613a6c572d3aa49@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22277' AND host = 'dynamic' [Jan 31 07:01:34] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Bah, we're expired (5/1201791689/1201791694)! [Jan 31 07:01:34] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22277' AND host = 'dynamic' [Jan 31 07:01:34] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Bah, we're expired (5/1201791689/1201791694)! [Jan 31 07:01:34] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22277' AND host = 'dynamic' [Jan 31 07:01:34] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Bah, we're expired (5/1201791689/1201791694)! [Jan 31 07:01:34] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Setting NAT on RTP to Off [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 627122fe19ac06fc64f3b08e4ec8fc67@81.198.164.48 - INVITE (With RTP) [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '1984979032' [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE host = '81.198.164.48' AND port = '5060' [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE ipaddr = '81.198.164.48' AND port = '5060' [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Setting NAT on RTP to On [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 3758d3ec587e15d344d60bc821fcf71e@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22231' AND host = 'dynamic' [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791691/1201791694)! [Jan 31 07:01:34] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:34] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 5da07f455dd598f549750c0451f3a910@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:34] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22230' AND host = 'dynamic' [Jan 31 07:01:34] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:35] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:35] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:35] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:34] DEBUG[26835] pbx.c: Function result is '112233' [Jan 31 07:01:35] DEBUG[26835] pbx.c: Launching 'System' [Jan 31 07:01:35] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (2/1201791692/1201791694)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 107bda65405f37c26bb344c572c78412@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22276' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 0a3f4a7d78a4efaa754a4bfb2dbd6d90@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22238' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 0a00aabc4de05ff1794d95eb14fc1883@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22278' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 613da4de086d07c9695c16941a3697ed@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22234' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 524911447d8d4cde799c9a1a5e34970c@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22254' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 47f24857567cf3094862b3bd4d08ba43@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22233' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (1/1201791694/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22231' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22230' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22276' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22238' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22278' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22277' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (6/1201791689/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22234' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22254' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22233' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (1/1201791694/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22231' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22230' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22276' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22238' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22278' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22234' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22254' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22233' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (1/1201791694/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22231' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22230' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22276' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22238' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22238' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22278' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22278' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22234' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22234' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22254' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22254' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22233' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (1/1201791694/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22233' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22277' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (6/1201791689/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22277' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22231' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (4/1201791691/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22231' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22230' AND host = 'dynamic' [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] chan_sip.c: Bah, we're expired (3/1201791692/1201791695)! [Jan 31 07:01:35] DEBUG[24778] db.c: Unable to find key '22230' in family 'SIP/Registry' [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Everything is fine. [Jan 31 07:01:35] DEBUG[24778] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22276' AND host = 'dynamic' [Jan 31 07:01:37] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:37] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:38] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:37] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:38] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:37] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:38] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:36] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:38] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:39] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:39] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:39] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:40] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:40] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:40] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:40] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:40] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:41] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:41] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:42] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:42] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:42] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:42] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:42] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:43] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:43] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:43] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:44] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:44] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:44] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:44] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:45] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:45] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:45] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:46] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:46] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:46] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:47] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:47] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:47] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:47] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:47] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:48] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:48] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:48] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:49] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:49] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:49] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:50] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:50] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:50] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:50] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:50] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:51] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:51] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:51] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:51] DEBUG[26315] rtp.c: Sending dtmf: 55 (7), at 81.198.164.48 [Jan 31 07:01:51] DEBUG[26315] rtp.c: Sending dtmf: 55 (7), at 81.198.164.48 [Jan 31 07:01:52] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:52] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:52] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:53] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:53] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:53] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:54] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:54] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:54] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:54] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:55] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:55] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:55] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:55] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:55] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:56] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:56] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:56] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:57] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:57] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:57] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:57] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:58] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:58] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:01:59] DEBUG[24764] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:59] NOTICE[24764] chan_iax2.c: Restricting registration for peer 'iaxmodem1' to 60 seconds (requested 300) [Jan 31 07:01:59] DEBUG[24768] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:01:59] NOTICE[24768] chan_iax2.c: Restricting registration for peer 'iaxmodem4' to 60 seconds (requested 300) [Jan 31 07:01:59] DEBUG[24764] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 13) [Jan 31 07:01:59] DEBUG[24764] chan_iax2.c: Acking anyway [Jan 31 07:01:59] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:59] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:01:59] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:01:59] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:00] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:00] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:00] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:00] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:00] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:01] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:01] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:01] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:02] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:02] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:02] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:02] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:02] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:03] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:03] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:04] DEBUG[24768] chan_iax2.c: Expiring registration for peer 'iaxmodem3' [Jan 31 07:02:04] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:04] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:04] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:05] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:05] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:05] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:05] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:06] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:06] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:06] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:07] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:07] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:07] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:07] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:07] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:08] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:08] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:08] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:09] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:09] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:09] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:10] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:10] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:10] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:10] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:10] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:11] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:11] WARNING[26704] app_addon_sql_mysql.c: mysql_real_connect(mysql,localhost,asterisk,dbpass,asterisk,...) failed [Jan 31 07:02:11] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:11] DEBUG[24768] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:02:11] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:11] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:12] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:12] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:12] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:12] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:12] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:13] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:14] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:14] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:14] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:15] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:14] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Bah, we're expired (42/1201791692/1201791734)! [Jan 31 07:02:15] DEBUG[24778] db.c: Unable to find key '22276' in family 'SIP/Registry' [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] sched.c: Request to schedule in the past?!?! [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '0a3f4a7d78a4efaa754a4bfb2dbd6d90@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '0a00aabc4de05ff1794d95eb14fc1883@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '613da4de086d07c9695c16941a3697ed@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '524911447d8d4cde799c9a1a5e34970c@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '47f24857567cf3094862b3bd4d08ba43@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '7ca944e203334b5e1613a6c572d3aa49@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '3758d3ec587e15d344d60bc821fcf71e@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Auto destroying SIP dialog '5da07f455dd598f549750c0451f3a910@127.0.0.1' [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: chan_sip: ast_sched_runq ran 39 all at once [Jan 31 07:02:15] DEBUG[24778] chan_sip.c: Allocating new SIP dialog for 0a3f4a7d78a4efaa754a4bfb2dbd6d90@127.0.0.1 - REGISTER (No RTP) [Jan 31 07:02:15] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:15] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:15] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:15] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:16] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:16] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:16] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:16] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:17] DEBUG[26405] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:17] DEBUG[26206] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:17] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:14] VERBOSE[26704] logger.c: -- Executing [17@local_dial:4] MYSQL("SIP/112233-06f73180", "Query result1 3 SELECT IF(ext_type='queue','queue','ext'), id, department_id, pause_on_wg_call, pause_on_direct_call, ring_time FROM extensions WHERE extension="17" AND (ext_type="queue" OR agent=1) AND ts_deleted IS NULL") in new stack [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Identifier 3, identifier_type 1 not found in identifier list [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: aMYSQL_query: Invalid connection identifier 3 passed in aMYSQL_query [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:5] MYSQL("SIP/112233-06f73180", "Fetch extension_callable 4 extension_type extension_id dpt_id pause_on_wg_call pause_on_direct_call ring_time") in new stack [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Identifier 4, identifier_type 2 not found in identifier list [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: aMYSQL_fetch: Invalid result identifier 4 passed [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:6] MYSQL("SIP/112233-06f73180", "Clear 4") in new stack [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Identifier 4, identifier_type 2 not found in identifier list [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Invalid result identifier 4 passed in aMYSQL_clear [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:7] MYSQL("SIP/112233-06f73180", "Query result1 3 SELECT extension FROM asteriskcdrdb.agent_extension_mapping WHERE agent="17"") in new stack [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Identifier 3, identifier_type 1 not found in identifier list [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: aMYSQL_query: Invalid connection identifier 3 passed in aMYSQL_query [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:8] MYSQL("SIP/112233-06f73180", "Fetch have_mapping 4 ext_db") in new stack [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Identifier 4, identifier_type 2 not found in identifier list [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: aMYSQL_fetch: Invalid result identifier 4 passed [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:9] MYSQL("SIP/112233-06f73180", "Clear 4") in new stack [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Identifier 4, identifier_type 2 not found in identifier list [Jan 31 07:02:17] WARNING[26704] app_addon_sql_mysql.c: Invalid result identifier 4 passed in aMYSQL_clear [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:10] Set("SIP/112233-06f73180", "__target_num=17") in new stack [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:11] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/target_num)=17") in new stack [Jan 31 07:02:17] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:12] Set("SIP/112233-06f73180", "__target_num_id=84") in new stack [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:13] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/target_num_id)=84") in new stack [Jan 31 07:02:17] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:17] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:14] GotoIf("SIP/112233-06f73180", "0?15:25") in new stack [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Goto (local_dial,17,25) [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:25] Set("SIP/112233-06f73180", "__B_extension=17") in new stack [Jan 31 07:02:17] DEBUG[26704] pbx.c: Launching 'Set' [Jan 31 07:02:17] VERBOSE[26704] logger.c: -- Executing [17@local_dial:26] Set("SIP/112233-06f73180", "DB(call_globals/1201791524.235/B_extension)=17") in new stack [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:27] NoOp("SIP/112233-06f73180", "Finish if-local_dial-86") in new stack [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'MYSQL' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:28] MYSQL("SIP/112233-06f73180", "Disconnect 3") in new stack [Jan 31 07:02:18] WARNING[26704] app_addon_sql_mysql.c: Identifier 3, identifier_type 1 not found in identifier list [Jan 31 07:02:18] WARNING[26704] app_addon_sql_mysql.c: Invalid connection identifier 3 passed in aMYSQL_disconnect [Jan 31 07:02:18] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:29] GotoIf("SIP/112233-06f73180", "0?30:37") in new stack [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Goto (local_dial,17,37) [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:37] NoOp("SIP/112233-06f73180", "Finish if-local_dial-87") in new stack [Jan 31 07:02:18] DEBUG[26704] pbx.c: Expression result is '0' [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:38] GotoIf("SIP/112233-06f73180", "0?39:39") in new stack [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Goto (local_dial,17,39) [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'NoOp' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:39] NoOp("SIP/112233-06f73180", "Finish if-local_dial-89") in new stack [Jan 31 07:02:18] DEBUG[26704] pbx.c: Expression result is '1' [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'GotoIf' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:40] GotoIf("SIP/112233-06f73180", "1?41:57") in new stack [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Goto (local_dial,17,41) [Jan 31 07:02:18] DEBUG[26704] pbx.c: Function result is '112233' [Jan 31 07:02:18] DEBUG[26704] pbx.c: Launching 'System' [Jan 31 07:02:18] VERBOSE[26704] logger.c: -- Executing [17@local_dial:41] System("SIP/112233-06f73180", "(sudo -u apache echo `date` 1201791524.235 SIP/112233-06f73180 112233 17 0 >> /var/log/asterisk/custom_logs/queue_`date +%Y-%m-%d`.log)&") in new stack [Jan 31 07:02:18] DEBUG[26315] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:14] DEBUG[24768] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 13) [Jan 31 07:02:18] DEBUG[24768] chan_iax2.c: Acking anyway [Jan 31 07:02:18] DEBUG[24768] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:02:14] VERBOSE[26835] logger.c: -- Executing [2943@default-external:3] System("SIP/112233-06f611d0", "(sudo -u apache echo `date` 1201791664.243 SIP/112233-06f611d0 112233 2943 0 >> /var/log/asterisk/custom_logs/incoming_`date +%Y-%m-%d`.log)&") in new stack [Jan 31 07:02:18] VERBOSE[24768] logger.c: -- Registered IAX2 'iaxmodem3' (AUTHENTICATED) at 127.0.0.1:4572 [Jan 31 07:02:18] NOTICE[24768] chan_iax2.c: Restricting registration for peer 'iaxmodem3' to 60 seconds (requested 300) [Jan 31 07:02:19] ERROR[24761] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 1347 (find_callno): Deadlock? waited 5 sec for mutex '&iaxsl[x]'? [Jan 31 07:02:19] ERROR[24761] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 5311 (register_verify): '&iaxsl[x]' was locked here. [Jan 31 07:02:19] ERROR[24765] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 1347 (find_callno): Deadlock? waited 5 sec for mutex '&iaxsl[x]'? [Jan 31 07:02:19] ERROR[24765] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 5311 (register_verify): '&iaxsl[x]' was locked here. [Jan 31 07:02:14] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:52] Goto("Local/22243@default-queue-4675,2", "44") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("Local/22243@default-queue-4675,2", "1?45:53") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,45) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_4_type' in family 'call_globals' [Jan 31 07:02:19] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_4_type not found in database. [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:45] Set("Local/22243@default-queue-4675,2", "__target_4_type=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_4_num' in family 'call_globals' [Jan 31 07:02:19] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_4_num not found in database. [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:46] Set("Local/22243@default-queue-4675,2", "__target_4_num=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_4_num_id' in family 'call_globals' [Jan 31 07:02:19] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_4_num_id not found in database. [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:47] Set("Local/22243@default-queue-4675,2", "__target_4_num_id=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_4_ext' in family 'call_globals' [Jan 31 07:02:19] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_4_ext not found in database. [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:48] Set("Local/22243@default-queue-4675,2", "__target_4_ext=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_4_ext_id' in family 'call_globals' [Jan 31 07:02:19] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_4_ext_id not found in database. [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:49] Set("Local/22243@default-queue-4675,2", "__target_4_ext_id=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] db.c: Unable to find key '1201791594.239/target_4_disposition' in family 'call_globals' [Jan 31 07:02:19] DEBUG[26838] func_db.c: DB: call_globals/1201791594.239/target_4_disposition not found in database. [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:50] Set("Local/22243@default-queue-4675,2", "__target_4_disposition=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '5' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:51] Set("Local/22243@default-queue-4675,2", "i=5") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:52] Goto("Local/22243@default-queue-4675,2", "44") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,44) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:44] GotoIf("Local/22243@default-queue-4675,2", "0?45:53") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,53) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:53] NoOp("Local/22243@default-queue-4675,2", "Finish for-read_vars-36") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:54] GotoIf("Local/22243@default-queue-4675,2", "1?55:56") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,55) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:55] Set("Local/22243@default-queue-4675,2", "__transfer_count=0") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:56] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-37") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:57] GotoIf("Local/22243@default-queue-4675,2", "1?58:59") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,58) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:58] Set("Local/22243@default-queue-4675,2", "__transfer_back=0") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:59] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-38") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:60] GotoIf("Local/22243@default-queue-4675,2", "1?61:62") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,61) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:61] Set("Local/22243@default-queue-4675,2", "__agent_call_counter_set=0") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:62] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-39") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:63] GotoIf("Local/22243@default-queue-4675,2", "0?64:65") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,65) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:65] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-40") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:66] GotoIf("Local/22243@default-queue-4675,2", "0?67:68") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,68) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:68] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-41") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:69] GotoIf("Local/22243@default-queue-4675,2", "0?70:71") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-read_vars,s,71) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:71] NoOp("Local/22243@default-queue-4675,2", "Finish if-read_vars-42") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-read_vars:72] NoOp("Local/22243@default-queue-4675,2", "-(E)------------------------------------- macro read_vars -----------") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Macro' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:5] Macro("Local/22243@default-queue-4675,2", "dumpvars") in new stack [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:1] NoOp("Local/22243@default-queue-4675,2", "-(B)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is 'ITN Economy Sales-----22901-----112233' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:2] NoOp("Local/22243@default-queue-4675,2", "CALLERIDNAME(CALLERIDNUM)[CALLINGPRES]=ITN Economy Sales-----22901-----112233(112233)[0]") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:3] NoOp("Local/22243@default-queue-4675,2", "DIALEDPEERNAME(DIALEDPEERNUMBER)[DIALEDTIME]DIALSTATUS=()[]") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:4] NoOp("Local/22243@default-queue-4675,2", "ANSWEREDTIME(UNIQUEID)PRIORITY=(1201791670.245)4 ### [HANGUPCAUSE]MEETMESECS=[0]") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:5] NoOp("Local/22243@default-queue-4675,2", "SIPDOMAIN= ### SIP_CODEC= ### SIPCALLID=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:6] NoOp("Local/22243@default-queue-4675,2", "TRANSFER_CONTEXT=transfer ### TXTCIDNAME= ### BLINDTRANSFER= ### TRANSFERSTATUS=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:7] NoOp("Local/22243@default-queue-4675,2", "TOUCH_MONITOR= ### CHANNEL=Local/22243@default-queue-4675,2") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:8] NoOp("Local/22243@default-queue-4675,2", "MACRO_CONTEXT=default-queue ### MACRO_EXTEN=22243 ### MACRO_PRIORITY=5") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:9] NoOp("Local/22243@default-queue-4675,2", "----------------- User variables ---------------") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:10] NoOp("Local/22243@default-queue-4675,2", "dnis=2943 agent(extension) A[()] -> B[22901(22901)]") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:11] NoOp("Local/22243@default-queue-4675,2", "business_hours=yes ### agent_auto_pause= ### workgroup_auto_pause=2 ### queue_ring_time=150") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:12] NoOp("Local/22243@default-queue-4675,2", "call_id-call_num=1201791594.239-4") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:13] NoOp("Local/22243@default-queue-4675,2", "call_from_queue=22901 ### direct_from_queue= ### queue_call= ### queue_call_num=3") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:14] NoOp("Local/22243@default-queue-4675,2", "transfer_count=0 ### transfer_to_agent= ### transfer_back=0 ### agent_call_counter_set=0") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:15] NoOp("Local/22243@default-queue-4675,2", "cdr_block_started=1") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:16] NoOp("Local/22243@default-queue-4675,2", "is_agent= ### have_mapping= ### agent_away=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:17] NoOp("Local/22243@default-queue-4675,2", "source_type=external ### source_num=112233 ### source_num_id= ### source_ext=8006772943 ### source_ext_id=70 ### source_dpt_id=1") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:18] NoOp("Local/22243@default-queue-4675,2", "middle_type= ### middle_num= ### middle_num_id= ### middle_ext= ### middle_ext_id= ### middle_dpt_id=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:19] NoOp("Local/22243@default-queue-4675,2", "target_type=queue ### target_num=22901 ### target_num_id=84 ### target_ext= ### target_ext_id= ### target_dpt_id=1") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:20] NoOp("Local/22243@default-queue-4675,2", "parent_channel=#SIP/112233-0746d320#Local/22243@default-queue-4675,2") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:21] Set("Local/22243@default-queue-4675,2", "i=1") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[1]=|||||") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '2' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=2") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[2]=|462|462|||") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '3' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=3") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[3]=queue|22901|84|||") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '4' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=4") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[4]=|||||") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '5' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=5") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:19] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "0?23:26") in new stack [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,26) [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:26] NoOp("Local/22243@default-queue-4675,2", "Finish for-dumpvars-1") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:27] NoOp("Local/22243@default-queue-4675,2", "v_data=") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:28] NoOp("Local/22243@default-queue-4675,2", "-(E)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:02:19] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:6] Set("Local/22243@default-queue-4675,2", "__A_extension=112233") in new stack [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:7] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/A_extension)=112233") in new stack [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:8] Set("Local/22243@default-queue-4675,2", "__A_agent=112233") in new stack [Jan 31 07:02:19] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:02:19] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:19] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:9] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/A_agent)=112233") in new stack [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[24827] rtp.c: Sending dtmf: 54 (6), at 81.198.164.48 [Jan 31 07:02:19] DEBUG[24827] rtp.c: Sending dtmf: 54 (6), at 81.198.164.48 [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:10] Set("Local/22243@default-queue-4675,2", "__queue_call=1") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Macro' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:11] Macro("Local/22243@default-queue-4675,2", "dumpvars") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:1] NoOp("Local/22243@default-queue-4675,2", "-(B)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Function result is 'ITN Economy Sales-----22901-----112233' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Function result is '112233' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:2] NoOp("Local/22243@default-queue-4675,2", "CALLERIDNAME(CALLERIDNUM)[CALLINGPRES]=ITN Economy Sales-----22901-----112233(112233)[0]") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:3] NoOp("Local/22243@default-queue-4675,2", "DIALEDPEERNAME(DIALEDPEERNUMBER)[DIALEDTIME]DIALSTATUS=()[]") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:4] NoOp("Local/22243@default-queue-4675,2", "ANSWEREDTIME(UNIQUEID)PRIORITY=(1201791670.245)4 ### [HANGUPCAUSE]MEETMESECS=[0]") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:5] NoOp("Local/22243@default-queue-4675,2", "SIPDOMAIN= ### SIP_CODEC= ### SIPCALLID=") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:6] NoOp("Local/22243@default-queue-4675,2", "TRANSFER_CONTEXT=transfer ### TXTCIDNAME= ### BLINDTRANSFER= ### TRANSFERSTATUS=") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:7] NoOp("Local/22243@default-queue-4675,2", "TOUCH_MONITOR= ### CHANNEL=Local/22243@default-queue-4675,2") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:8] NoOp("Local/22243@default-queue-4675,2", "MACRO_CONTEXT=default-queue ### MACRO_EXTEN=22243 ### MACRO_PRIORITY=11") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Noop [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:9] NoOp("Local/22243@default-queue-4675,2", "----------------- User variables ---------------") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:10] NoOp("Local/22243@default-queue-4675,2", "dnis=2943 agent(extension) A[112233(112233)] -> B[22901(22901)]") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:11] NoOp("Local/22243@default-queue-4675,2", "business_hours=yes ### agent_auto_pause= ### workgroup_auto_pause=2 ### queue_ring_time=150") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:12] NoOp("Local/22243@default-queue-4675,2", "call_id-call_num=1201791594.239-4") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:13] NoOp("Local/22243@default-queue-4675,2", "call_from_queue=22901 ### direct_from_queue= ### queue_call=1 ### queue_call_num=3") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:14] NoOp("Local/22243@default-queue-4675,2", "transfer_count=0 ### transfer_to_agent= ### transfer_back=0 ### agent_call_counter_set=0") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:15] NoOp("Local/22243@default-queue-4675,2", "cdr_block_started=1") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:16] NoOp("Local/22243@default-queue-4675,2", "is_agent= ### have_mapping= ### agent_away=") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:17] NoOp("Local/22243@default-queue-4675,2", "source_type=external ### source_num=112233 ### source_num_id= ### source_ext=8006772943 ### source_ext_id=70 ### source_dpt_id=1") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:18] NoOp("Local/22243@default-queue-4675,2", "middle_type= ### middle_num= ### middle_num_id= ### middle_ext= ### middle_ext_id= ### middle_dpt_id=") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:19] NoOp("Local/22243@default-queue-4675,2", "target_type=queue ### target_num=22901 ### target_num_id=84 ### target_ext= ### target_ext_id= ### target_dpt_id=1") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:20] NoOp("Local/22243@default-queue-4675,2", "parent_channel=#SIP/112233-0746d320#Local/22243@default-queue-4675,2") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:21] Set("Local/22243@default-queue-4675,2", "i=1") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[1]=|||||") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '2' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=2") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[2]=|462|462|||") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '3' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=3") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[3]=queue|22901|84|||") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '4' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=4") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '1' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "1?23:26") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,23) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("Local/22243@default-queue-4675,2", "target[4]=|||||") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '5' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:24] Set("Local/22243@default-queue-4675,2", "i=5") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Set [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:25] Goto("Local/22243@default-queue-4675,2", "22") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,22) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: Goto [Jan 31 07:02:20] DEBUG[26838] pbx.c: Expression result is '0' [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'GotoIf' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:22] GotoIf("Local/22243@default-queue-4675,2", "0?23:26") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (macro-dumpvars,s,26) [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: GotoIf [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:26] NoOp("Local/22243@default-queue-4675,2", "Finish for-dumpvars-1") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:27] NoOp("Local/22243@default-queue-4675,2", "v_data=") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'NoOp' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [s@macro-dumpvars:28] NoOp("Local/22243@default-queue-4675,2", "-(E)------------------------------------- dumpvars ---------------") in new stack [Jan 31 07:02:20] DEBUG[26838] app_macro.c: Executed application: NoOp [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:12] Set("Local/22243@default-queue-4675,2", "__TRANSFER_CONTEXT=transfer") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:13] Set("Local/22243@default-queue-4675,2", "__prev_receiver=") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:14] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/prev_receiver)=") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:15] Set("Local/22243@default-queue-4675,2", "__receiver=22243") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:16] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/receiver)=22243") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:17] Set("Local/22243@default-queue-4675,2", "__target_num=22243") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:18] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/target_num)=22243") in new stack [Jan 31 07:02:19] DEBUG[26784] app_queue.c: It's not our turn (SIP/112233-078fab30). [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Goto' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@default-queue:19] Goto("Local/22243@default-queue-4675,2", "local_dial|22243|1") in new stack [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Goto (local_dial,22243,1) [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@local_dial:1] Set("Local/22243@default-queue-4675,2", "__B_agent=22243") in new stack [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'Set' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@local_dial:2] Set("Local/22243@default-queue-4675,2", "DB(call_globals/1201791594.239/B_agent)=22243") in new stack [Jan 31 07:02:19] DEBUG[26765] app_queue.c: It's not our turn (SIP/112233-07083600). [Jan 31 07:02:20] DEBUG[26765] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:20] DEBUG[26305] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:20] DEBUG[26784] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:20] DEBUG[26838] pbx.c: Launching 'MYSQL' [Jan 31 07:02:20] VERBOSE[26838] logger.c: -- Executing [22243@local_dial:3] MYSQL("Local/22243@default-queue-4675,2", "Connect connid localhost asterisk AstStgPw09 asterisk") in new stack [Jan 31 07:02:19] DEBUG[26753] rtp.c: Got RTCP report of 64 bytes [Jan 31 07:02:19] ERROR[24759] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 1347 (find_callno): Deadlock? waited 5 sec for mutex '&iaxsl[x]'? [Jan 31 07:02:21] ERROR[24759] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 5311 (register_verify): '&iaxsl[x]' was locked here. [Jan 31 07:02:14] DEBUG[24762] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jan 31 07:02:21] NOTICE[24762] chan_iax2.c: Restricting registration for peer 'iaxmodem1' to 60 seconds (requested 300) [Jan 31 07:02:19] ERROR[24763] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: chan_iax2.c line 1347 (find_callno): Deadlock? waited 5 sec for mutex '&iaxsl[x]'? [Jan 31 07:02:21] ERROR[24763] /usr/dist/asterisk-1.4.18-rc1/include/asterisk/lock.h: