[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:77] Set("SIP/112233-b546b218", "DB(call_globals/1201807480.281/target_3_type)=queue") in new stack
[Jan 31 11:24:41] DEBUG[24887] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[25183] manager.c: Manager received command 'Login'
[Jan 31 11:24:41] VERBOSE[25183] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Jan 31 11:24:41] DEBUG[25183] config.c: Parsing /etc/asterisk/manager.conf
[Jan 31 11:24:41] VERBOSE[25183] logger.c: Found
[Jan 31 11:24:41] DEBUG[25183] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
[Jan 31 11:24:41] DEBUG[25183] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
[Jan 31 11:24:41] DEBUG[25183] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
[Jan 31 11:24:41] DEBUG[25183] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
[Jan 31 11:24:41] VERBOSE[25183] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[Jan 31 11:24:41] DEBUG[25183] manager.c: Manager received command 'Command'
[Jan 31 11:24:41] DEBUG[25183] manager.c: Manager received command 'Command'
[Jan 31 11:24:41] VERBOSE[25183] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:78] Set("SIP/112233-b546b218", "__target_3_num_id=84") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:79] Set("SIP/112233-b546b218", "DB(call_globals/1201807480.281/target_3_num_id)=84") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:80] Set("SIP/112233-b546b218", "__target_3_num=22901") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:81] Set("SIP/112233-b546b218", "DB(call_globals/1201807480.281/target_3_num)=22901") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:82] Set("SIP/112233-b546b218", "__target_3_ext_id=") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:83] Set("SIP/112233-b546b218", "DB(call_globals/1201807480.281/target_3_ext_id)=") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:84] Set("SIP/112233-b546b218", "__target_3_ext=") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'Set'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:85] Set("SIP/112233-b546b218", "DB(call_globals/1201807480.281/target_3_ext)=") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: Set
[Jan 31 11:24:41] DEBUG[25165] pbx.c: Launching 'NoOp'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing [s@macro-cdr_block_start:86] NoOp("SIP/112233-b546b218", "-(E)------------------------------------- macro cdr_block_start(queue|22901) -----------") in new stack
[Jan 31 11:24:41] DEBUG[25165] app_macro.c: Executed application: NoOp
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '16'
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '16'
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '16'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Executing Queue("SIP/112233-b546b218", "22901|t|||300")
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: SIP/112233-b546b218: Got priority 0 from ${QUEUE_PRIO}.
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: queue: 22901, options: t, url: , announce: , expires: 1201807781, priority: 0
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_table WHERE name = '22901'
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:41] DEBUG[25165] 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 11:24:41] DEBUG[25165] app_queue.c: Queue '22901' Join, Channel 'SIP/112233-b546b218', Position '1'
[Jan 31 11:24:41] VERBOSE[25165] logger.c:     -- Started music on hold, class 'ASAP', on SIP/112233-b546b218
[Jan 31 11:24:41] DEBUG[25165] channel.c: Scheduling timer at 160 sample intervals
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: It's our turn (SIP/112233-b546b218).
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: SIP/112233-b546b218 is trying to call a queue member.
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22206' with metric 999984
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22275' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22278' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22231' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22237' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22232' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22230' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22222' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22225' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22221' with metric 5000000
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22227' with metric 5999695
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22273' with metric 5999735
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22238' with metric 5999752
[Jan 31 11:24:41] DEBUG[23527] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22235' with metric 5999839
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22246' with metric 5999848
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22248' with metric 5999865
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22242' with metric 5999870
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22272' with metric 5999893
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22256' with metric 5999917
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22279' with metric 5999927
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Trying 'Agent/22239' with metric 5999970
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Nobody left to try ringing in queue
[Jan 31 11:24:41] DEBUG[25165] app_queue.c: Everyone is busy at this time
[Jan 31 11:24:41] DEBUG[25165] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:41] DEBUG[25165] 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 11:24:41] DEBUG[25165] res_musiconhold.c: SIP/112233-b546b218 Opened file 0 '/var/lib/asterisk/moh-playlists/ASAP/OH-generic-contemp-2'
[Jan 31 11:24:41] DEBUG[25165] rtp.c: Ooh, format changed from unknown to ulaw
[Jan 31 11:24:41] DEBUG[25165] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jan 31 11:24:41] DEBUG[25165] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 11:24:41] DEBUG[23788] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24825] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24998] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24363] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24877] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[23527] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24589] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[25032] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24719] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:41] DEBUG[24589] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[24887] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[23788] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[24956] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[24363] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[23469] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[24355] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[25067] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[23222] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[23559] rtp.c: Sending dtmf: 49 (1), at 81.198.164.48
[Jan 31 11:24:42] DEBUG[25147] rtp.c: Got RTCP report of 44 bytes
[Jan 31 11:24:42] DEBUG[23559] rtp.c: Sending dtmf: 49 (1), at 81.198.164.48
[Jan 31 11:24:42] DEBUG[23222] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[25119] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Spawn extension (static_ivr,workgroup_login,12) exited non-zero on 'SIP/22246-b54495d8'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:   == Spawn extension (static_ivr, workgroup_login, 12) exited non-zero on 'SIP/22246-b54495d8'
[Jan 31 11:24:42] DEBUG[25119] channel.c: Soft-Hanging up channel 'SIP/22246-b54495d8'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'Goto'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@static_ivr:1] Goto("SIP/22246-b54495d8", "hangup_callback|h|1") in new stack
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Goto (hangup_callback,h,1)
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:1] NoOp("SIP/22246-b54495d8", "-(B)----------------------- context hangup_callback h --------------------------") in new stack
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'Macro'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:2] Macro("SIP/22246-b54495d8", "dumpvars") in new stack
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:1] NoOp("SIP/22246-b54495d8", "-(B)------------------------------------- dumpvars ---------------") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Function result is 'device'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Function result is '22246'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:2] NoOp("SIP/22246-b54495d8", "CALLERIDNAME(CALLERIDNUM)[CALLINGPRES]=device(22246)[0]") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:3] NoOp("SIP/22246-b54495d8", "DIALEDPEERNAME(DIALEDPEERNUMBER)[DIALEDTIME]DIALSTATUS=()[]") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:4] NoOp("SIP/22246-b54495d8", "ANSWEREDTIME(UNIQUEID)PRIORITY=(1201807465.273)4 ### [HANGUPCAUSE]MEETMESECS=[0]") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:5] NoOp("SIP/22246-b54495d8", "SIPDOMAIN=81.198.164.117 ### SIP_CODEC= ### SIPCALLID=67966a500f7e0f39325f7e227373b5fb@81.198.164.48") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:6] NoOp("SIP/22246-b54495d8", "TRANSFER_CONTEXT=transfer ### TXTCIDNAME= ### BLINDTRANSFER= ### TRANSFERSTATUS=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:7] NoOp("SIP/22246-b54495d8", "TOUCH_MONITOR= ### CHANNEL=SIP/22246-b54495d8") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:8] NoOp("SIP/22246-b54495d8", "MACRO_CONTEXT=hangup_callback ### MACRO_EXTEN=h ### MACRO_PRIORITY=2") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Noop
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:9] NoOp("SIP/22246-b54495d8", "----------------- User variables ---------------") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:10] NoOp("SIP/22246-b54495d8", "dnis= agent(extension) A[22246(22246)] -> B[()]") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:11] NoOp("SIP/22246-b54495d8", "business_hours= ### agent_auto_pause= ### workgroup_auto_pause= ### queue_ring_time=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:12] NoOp("SIP/22246-b54495d8", "call_id-call_num=1201807465.273-1") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:13] NoOp("SIP/22246-b54495d8", "call_from_queue=0 ### direct_from_queue= ### queue_call= ### queue_call_num=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:14] NoOp("SIP/22246-b54495d8", "transfer_count=0 ### transfer_to_agent=054 ### transfer_back=0 ### agent_call_counter_set=0") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:15] NoOp("SIP/22246-b54495d8", "cdr_block_started=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:16] NoOp("SIP/22246-b54495d8", "is_agent=1 ### have_mapping=0 ### agent_away=0") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:17] NoOp("SIP/22246-b54495d8", "source_type=agent ### source_num=22246 ### source_num_id=34327 ### source_ext= ### source_ext_id= ### source_dpt_id=1") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:18] NoOp("SIP/22246-b54495d8", "middle_type= ### middle_num= ### middle_num_id= ### middle_ext= ### middle_ext_id= ### middle_dpt_id=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:19] NoOp("SIP/22246-b54495d8", "target_type= ### target_num= ### target_num_id= ### target_ext= ### target_ext_id= ### target_dpt_id=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:20] NoOp("SIP/22246-b54495d8", "parent_channel=#SIP/22246-b54495d8") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Expression result is '1'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'Set'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:21] Set("SIP/22246-b54495d8", "i=1") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Set
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Expression result is '1'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'GotoIf'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:22] GotoIf("SIP/22246-b54495d8", "1?23:26") in new stack
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Goto (macro-dumpvars,s,23)
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: GotoIf
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:23] NoOp("SIP/22246-b54495d8", "target[1]=|||||") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Expression result is '2'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'Set'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:24] Set("SIP/22246-b54495d8", "i=2") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Set
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'Goto'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:25] Goto("SIP/22246-b54495d8", "22") in new stack
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Goto (macro-dumpvars,s,22)
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: Goto
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Expression result is '0'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'GotoIf'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:22] GotoIf("SIP/22246-b54495d8", "0?23:26") in new stack
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Goto (macro-dumpvars,s,26)
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: GotoIf
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:26] NoOp("SIP/22246-b54495d8", "Finish for-dumpvars-1") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:27] NoOp("SIP/22246-b54495d8", "v_data=") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [s@macro-dumpvars:28] NoOp("SIP/22246-b54495d8", "-(E)------------------------------------- dumpvars ---------------") in new stack
[Jan 31 11:24:42] DEBUG[25119] app_macro.c: Executed application: NoOp
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Expression result is '0'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'GotoIf'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:3] GotoIf("SIP/22246-b54495d8", "0?4:9") in new stack
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Goto (hangup_callback,h,9)
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Expression result is '0'
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'GotoIf'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:9] GotoIf("SIP/22246-b54495d8", "0?10:13") in new stack
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Goto (hangup_callback,h,13)
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:13] NoOp("SIP/22246-b54495d8", "No callback type set") in new stack
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:14] NoOp("SIP/22246-b54495d8", "Finish if-if-hangup_callback-124-126") in new stack
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:15] NoOp("SIP/22246-b54495d8", "Finish if-hangup_callback-124") in new stack
[Jan 31 11:24:42] DEBUG[25119] pbx.c: Launching 'NoOp'
[Jan 31 11:24:42] VERBOSE[25119] logger.c:     -- Executing [h@hangup_callback:16] NoOp("SIP/22246-b54495d8", "-(E)----------------------- context hangup_callback h --------------------------") in new stack
[Jan 31 11:24:42] DEBUG[25119] channel.c: Hanging up channel 'SIP/22246-b54495d8'
[Jan 31 11:24:42] DEBUG[25119] chan_sip.c: Hangup call SIP/22246-b54495d8, SIP callid 67966a500f7e0f39325f7e227373b5fb@81.198.164.48)
[Jan 31 11:24:42] DEBUG[22802] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:42] DEBUG[22802] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22246-b54495d8' AND host = 'dynamic'
[Jan 31 11:24:42] DEBUG[22802] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:42] DEBUG[22802] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22246-b54495d8'
[Jan 31 11:24:42] DEBUG[22802] res_config_mysql.c: MySQL RealTime: Everything is fine.
[Jan 31 11:24:42] DEBUG[22802] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '22246' AND host = 'dynamic'
[Jan 31 11:24:42] DEBUG[24673] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[24763] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[24956] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[25147] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 11:24:42] DEBUG[25147] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 11:24:42] DEBUG[24485] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:42] DEBUG[25120] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[24424] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[23559] rtp.c: Sending dtmf: 42 (*), at 81.198.164.48
[Jan 31 11:24:43] DEBUG[25067] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[23559] rtp.c: Sending dtmf: 42 (*), at 81.198.164.48
[Jan 31 11:24:43] DEBUG[24763] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[25147] rtp.c: Sending dtmf: 50 (2), at 81.198.164.48
[Jan 31 11:24:43] DEBUG[24485] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[25147] rtp.c: Sending dtmf: 50 (2), at 81.198.164.48
[Jan 31 11:24:43] DEBUG[23559] rtp.c: Sending dtmf: 54 (6), at 81.198.164.48
[Jan 31 11:24:43] DEBUG[24673] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[23559] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:43] DEBUG[23559] rtp.c: Sending dtmf: 54 (6), at 81.198.164.48
[Jan 31 11:24:44] DEBUG[25147] rtp.c: Sending dtmf: 50 (2), at 81.198.164.48
[Jan 31 11:24:44] DEBUG[25147] rtp.c: Sending dtmf: 50 (2), at 81.198.164.48
[Jan 31 11:24:44] DEBUG[24719] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:44] DEBUG[23712] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:44] DEBUG[25147] rtp.c: Sending dtmf: 50 (2), at 81.198.164.48
[Jan 31 11:24:44] DEBUG[24395] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:44] DEBUG[25147] rtp.c: Sending dtmf: 50 (2), at 81.198.164.48
[Jan 31 11:24:44] DEBUG[24793] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:44] DEBUG[23712] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:44] DEBUG[25032] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[24395] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[25120] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[25147] rtp.c: Sending dtmf: 55 (7), at 81.198.164.48
[Jan 31 11:24:45] DEBUG[25147] rtp.c: Sending dtmf: 55 (7), at 81.198.164.48
[Jan 31 11:24:45] DEBUG[23559] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[24793] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[23436] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[24424] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[24825] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[23436] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[25165] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:45] DEBUG[24998] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:46] DEBUG[25147] rtp.c: Sending dtmf: 55 (7), at 81.198.164.48
[Jan 31 11:24:46] DEBUG[24887] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:46] DEBUG[25147] rtp.c: Sending dtmf: 55 (7), at 81.198.164.48
[Jan 31 11:24:46] DEBUG[23527] rtp.c: Got RTCP report of 64 bytes
[Jan 31 11:24:46] DEBUG[24355] audiohook.c: Failed to get 160 samples from write factory 0xb51a07a4
[Jan 31 11:24:46] DEBUG[25067] channel.c: Didn't get a frame from channel: SIP/112233-b54f3df0
[Jan 31 11:24:46] DEBUG[25067] channel.c: Bridge stops bridging channels SIP/112233-b54f3df0 and Agent/22222
[Jan 31 11:24:46] DEBUG[25067] channel.c: Hanging up channel 'Agent/22222'
[Jan 31 11:24:46] DEBUG[25067] chan_agent.c: Hangup called for state Up
[Jan 31 11:24:46] DEBUG[25067] channel.c: Hanging up channel 'SIP/22222-0897c398'
[Jan 31 11:24:46] DEBUG[25067] chan_sip.c: Hangup call SIP/22222-0897c398, SIP callid 18c1b2932b39857d09db42546c44a6dd@81.198.164.117)
[Jan 31 11:24:46] DEBUG[22825] chan_sip.c: Stopping retransmission on '18c1b2932b39857d09db42546c44a6dd@81.198.164.117' of Request 103: Match Not Found
[Jan 31 11:24:46] DEBUG[24355] channel.c: Scheduling timer at 0 sample intervals
[Jan 31 11:24:46] VERBOSE[24355] logger.c:   == Done Spying on channel SIP/22222-0897c398
[Jan 31 11:24:50] VERBOSE[25199] logger.c: Asterisk Event Logger Started /var/log/asterisk/event_log
[Jan 31 11:24:50] VERBOSE[25199] logger.c: Asterisk Dynamic Loader Starting:
[Jan 31 11:24:50] VERBOSE[25199] logger.c:   == Parsing '/etc/asterisk/modules.conf': [Jan 31 11:24:50] DEBUG[25199] config.c: Parsing /etc/asterisk/modules.conf