Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Paging/Intercom seems to be not working on cisco 7960/7940 #57

Open
samam9911 opened this issue Jan 11, 2022 · 5 comments
Open

Paging/Intercom seems to be not working on cisco 7960/7940 #57

samam9911 opened this issue Jan 11, 2022 · 5 comments
Assignees
@dkgroot @steve-lad
Labels
question Further information is requested

Comments

@samam9911
Copy link

When I try to intercom or page a phone, it rings twice and disconnects instead of auto answer. Not sure if all models do that but all I have is 7960 and 7940.
am I missing a setting that would correct this behavior? I searched the issues but didn't find anything about it
Thanks!
@steve-lad
Copy link
Collaborator

@dkgroot default AutoAnswerRingTime is respected, but why the disconnect?

@samam9911
Copy link
Author

Any one tried paging pro with cisco sccp (not sip) phones? Does multicast work? from what I read that the phones need to be configured to listen to the multicasting ip:port (maybe xml push), would paging pro be able to communicate and configure the phones to listen to the multicasting port:ip?

@dkgroot
Copy link
Member

dkgroot commented Jan 26, 2022 •
edited
Loading

@samam9911

  1. I don't use freepbx, so i don't know what it uses to perform intercom / paging. I am assuming the simply call multiple phones at ones and put them in a large one way bridge. To make paging working in this simple fashion you need to follow: FreePBX_Intercom-Paging-HowTo to support sccp phones. I don't know why it would be disconnecting, if that is the case after reading the wiki page and applying the changes, then go to point 3, below.
  2. I don't know what "paging pro" is, sorry. SCCP phones do support unicast and multicast and they would be perfect for paging/intercom solution. You can find more about that here: Multicast-Paging. And yes doing an cXML push to the phone is part of the process. And you also need to make sure your switches/routers are setup to support/forward multicast traffic.
  3. When reporting issues with chan-sccp, then I need to see the see the asterisk cli logging to verify this and make an educated guess about what might be going down. Do set core set verbose 5, core set debug 1, sccp debug core, channel, indicate, pbx before paging anyone. Collect the logs and attach them here. But do make sure you check out those wiki pages before.

@dkgroot dkgroot added the question Further information is requested label Jan 26, 2022
@samam9911
Copy link
Author

with the marco-2way-answer added in custom_extensions file, paging works. Multicasting still acts as individual paging, so for 70 phones it will dial 70 extensions which is a kill

@mbielech5
Copy link

Hello All:

I too am having an issue with the paging/intercom in FreePBX and chan-sccp. I have paging working with both the Cisco and non-Cisco phones together, and intercom works by dialing a Cisco intercom extension from a non-Cisco extension (e.g. PJSIP and MicroSIP), but dialing a Cisco intercom extension from another Cisco extension (regardless if it is an intercom extension or not), the destination phone will not auto-answer and pick up the call. Instead, the phone just keeps ringing.

I have tried this between a Cisco 7961 and a 7960, as well as between two Cisco 7961 phones with the same result. I have also followed the FreePBX_Intercom Paging HowTo instructions and added the intercom extensions to the Asterisk database for autoanswer macro. To summarize:

PJSIP Phone --> Paging Group = All phones work and auto-answer
Cisco Phone --> Paging Group = All phones work and auto-answer
PJSIP Phone --> Cisco Intercom Extension = Cisco phone picks up and auto-answers
Cisco Phone --> Another Cisco Intercom Extension = Cisco phone does not pick up and the call keeps ringing.

Below is an Asterisk console debug output if this can help anyone with this problem; and I am also wondering if anyone else has this problem or if it is something I may have misconfigured. Below is when I called from a Cisco 7961 non-intercom extension 612 to a Cisco 7960 intercom extension 707:

[2022-04-16 22:00:01] DEBUG[8653]: manager.c:6678 process_message: Running action 'Login'
SEP002D4482438A: (getEmptyChannel) on line:612, maybe_c:
    -- SEP002D4482438A: Getting the active channel on device.
    -- SEP002D4482438A: No active channel on device.
    -- SEP002D4482438A: Set the active channel 11 on device
    -- 3: New channel number: 11 on line 612
    -- SCCP: (pbx_channel_allocate) try to allocate Outbound channel on line: 612
    -- SCCP:             cid_num:
    -- SCCP:            cid_name: Mark x612
    -- SCCP:         accountcode: 612
    -- SCCP:               exten:
    -- SCCP:             context: from-internal
    -- SCCP:            amaflags: 0
    -- SCCP:           chan/call: SCCP/612-0000000B
    -- SCCP: combined audio caps: [slin16, g722/64k, ulaw/64k, alaw/64k, g722/56k, g722/48k, g729b, g729ab, g729, g729a]
    -- SCCP: reduced audio prefs: [g722/64k, g722/56k, g722/48k, ulaw/64k, alaw/64k]
    -- SCCP: combined video caps: []
    -- SCCP: reduced video prefs: []
    -- SCCP: (allocPBXChannel) Create New Channel with name: SCCP/612-0000000B
[2022-04-16 22:00:02] DEBUG[7842]: stasis.c:614 stasis_topic_create_with_detail: Topic 'channel:1650160802.113': 0x24e0270 created
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:949 __ast_channel_alloc_ap: Channel 0x273bda0 'SCCP/612-0000000B' allocated
[2022-04-16 22:00:02] DEBUG[7842]: rtp_engine.c:526 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x2067820'
[2022-04-16 22:00:02] DEBUG[7842]: res_rtp_asterisk.c:3871 rtp_allocate_transport: (0x2067820) RTP allocated port 14044
[2022-04-16 22:00:02] DEBUG[7842]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance '0x2067820' is setup and ready to go
[2022-04-16 22:00:02] DEBUG[7842]: res_rtp_asterisk.c:8440 ast_rtp_prop_set: (0x2067820) RTCP setup on RTP instance
  == Using SCCP RTP TOS bits 184
    -- 3: Allocated asterisk channel SCCP/612-0000000B
    -- SEP002D4482438A: Indicate SCCP new state:SPEEDDIAL, current channel state:DOWN on call:SCCP/612-0000000B, lineInstance:1 (previous channelstate:DOWN)
    -- SEP002D4482438A: Finish to indicate channel state:SPEEDDIAL on call:SCCP/612-0000000B, lineInstance:1. New channel state:OFFHOOK
    -- SEP002D4482438A: (sccp_pbx_softswitch) New call on line 612
    -- SEP002D4482438A: (sccp_pbx_softswitch) Dial Extension 707
    -- SEP002D4482438A: Indicate SCCP new state:DIALING, current channel state:OFFHOOK on call:SCCP/612-0000000B, lineInstance:1 (previous channelstate:DOWN)
    -- SEP002D4482438A: Send the dialed number:707, callid:11, lineInstance:1
    -- SEP002D4482438A: Finish to indicate channel state:DIALING on call:SCCP/612-0000000B, lineInstance:1. New channel state:DIALING
    -- SCCP: (sccp_pbx_softswitch) set variable SKINNY_PRIVATE to: 0
    -- SCCP: (sccp_pbx_softswitch) set variable SKINNY_PRIVATE to: 1
    -- +- pbx extension matcher (707            ): ---+
    -- |ignore     |exists     |can match  |match more|
    -- | no        |yes        |yes        |yes       |
    -- +----------------------------------------------+
 SEP002D4482438A: (sccp_pbx_softswitch) channel SCCP/612-0000000B is dialing number 707
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:5825 set_format: Channel SCCP/612-0000000B setting write format path: slin -> g722
    -- SEP002D4482438A: Asterisk prodded channel SCCP/612-0000000B.
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:8265 ast_channel_start_silence_generator: Started silence generator on 'SCCP/612-0000000B'
[2022-04-16 22:00:02] DEBUG[2597]: db.c:392 db_get_common: Unable to find key 'DND612' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:8300 ast_channel_stop_silence_generator: Stopped silence generator on 'SCCP/612-0000000B'
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:5825 set_format: Channel SCCP/612-0000000B setting write format path: g722 -> g722
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:5825 set_format: Channel SCCP/612-0000000B setting write format path: slin -> g722
    -- SEP002D4482438A: Asterisk prodded channel SCCP/612-0000000B.
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:8265 ast_channel_start_silence_generator: Started silence generator on 'SCCP/612-0000000B'
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:8300 ast_channel_stop_silence_generator: Stopped silence generator on 'SCCP/612-0000000B'
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:5825 set_format: Channel SCCP/612-0000000B setting write format path: g722 -> g722
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:5825 set_format: Channel SCCP/612-0000000B setting write format path: slin -> g722
    -- SEP002D4482438A: Asterisk prodded channel SCCP/612-0000000B.
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:8265 ast_channel_start_silence_generator: Started silence generator on 'SCCP/612-0000000B'
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:8300 ast_channel_stop_silence_generator: Stopped silence generator on 'SCCP/612-0000000B'
[2022-04-16 22:00:02] DEBUG[7842]: channel.c:5825 set_format: Channel SCCP/612-0000000B setting write format path: g722 -> g722
    -- SCCP/612-0000000B: (pbx_pbx_start) autoloop has started, set requestHangup = requestQueueHangup
 SEP002D4482438A: (sccp_pbx_softswitch) pbx started
 SEP002D4482438A: (sccp_pbx_softswitch) finished
 SCCP: (sccp_pbx_softswitch) exit
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [707@from-internal:1] GotoIf("SCCP/612-0000000B", "0?ext-local,*707,1") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [707@from-internal:2] GotoIf("SCCP/612-0000000B", "1?ext-local,707,1:followme-check,707,1") in new stack
    -- Goto (ext-local,707,1)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [707@ext-local:1] Set("SCCP/612-0000000B", "__RINGTIMER=1") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_strings.c:1037 regex: FUNCTION REGEX (from-queue)(SCCP/612-0000000B)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [707@ext-local:2] ExecIf("SCCP/612-0000000B", "0?Set(__CWIGNORE=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Macro'
    -- Executing [707@ext-local:3] Macro("SCCP/612-0000000B", "exten-vm,novm,707,0,0,0") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Macro'
    -- Executing [s@macro-exten-vm:1] Macro("SCCP/612-0000000B", "user-callerid,") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:1] Set("SCCP/612-0000000B", "TOUCH_MONITOR=1650160802.113") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:2] Set("SCCP/612-0000000B", "CHANCONTEXT=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:3] Set("SCCP/612-0000000B", "CHANCONTEXT=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:4] Set("SCCP/612-0000000B", "CHANEXTENCONTEXT=612-0000000B") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:5] Set("SCCP/612-0000000B", "CHANEXTEN=612-0000000B") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:6] Set("SCCP/612-0000000B", "CALLERID(number)=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:7] Set("SCCP/612-0000000B", "AMPUSER=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:8] Set("SCCP/612-0000000B", "HOTDESCKCHAN=612-0000000B") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:9] Set("SCCP/612-0000000B", "HOTDESKEXTEN=612") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:10] Set("SCCP/612-0000000B", "HOTDESKCALL=0") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '612/user' in family 'EDEVICE'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: EDEVICE/612/user not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:11] ExecIf("SCCP/612-0000000B", "0?Set(HOTDESKCALL=1)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '612/user' in family 'EDEVICE'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: EDEVICE/612/user not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '612/location' in family 'EDEVICE'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: EDEVICE/612/location not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:12] ExecIf("SCCP/612-0000000B", "0?Set(CALLERID(name)=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '612/location' in family 'EDEVICE'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: EDEVICE/612/location not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:13] GotoIf("SCCP/612-0000000B", "0?report") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:14] ExecIf("SCCP/612-0000000B", "1?Set(REALCALLERIDNUM=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/user' in family 'DEVICE'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: DEVICE//user not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:15] Set("SCCP/612-0000000B", "AMPUSER=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:16] GotoIf("SCCP/612-0000000B", "0?limit") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/cidname' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER//cidname not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:17] Set("SCCP/612-0000000B", "AMPUSERCIDNAME=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/cidnum' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/cidnum' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER//cidnum not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:18] ExecIf("SCCP/612-0000000B", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/cidnum' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/cidnum' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER//cidnum not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:19] GotoIf("SCCP/612-0000000B", "1?report") in new stack
    -- Goto (macro-user-callerid,s,28)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-user-callerid:28] NoOp("SCCP/612-0000000B", "Macro Depth is 2") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:29] GotoIf("SCCP/612-0000000B", "1?report2:macroerror") in new stack
    -- Goto (macro-user-callerid,s,30)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:30] GotoIf("SCCP/612-0000000B", "0?continue") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707/accountcode' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/707/accountcode not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:31] ExecIf("SCCP/612-0000000B", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707/accountcode' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/707/accountcode not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '-1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:32] Set("SCCP/612-0000000B", "__TTL=64") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:33] GotoIf("SCCP/612-0000000B", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,49)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:49] Set("SCCP/612-0000000B", "CALLERID(number)=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:50] Set("SCCP/612-0000000B", "CALLERID(name)=Mark x612") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:51] GotoIf("SCCP/612-0000000B", "0?cnum") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:52] Set("SCCP/612-0000000B", "CDR(cnam)=Mark x612") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:53] Set("SCCP/612-0000000B", "CDR(cnum)=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:54] Set("SCCP/612-0000000B", "CHANNEL(language)=en") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Macro
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-exten-vm:2] Set("SCCP/612-0000000B", "RingGroupMethod=none") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-exten-vm:3] Set("SCCP/612-0000000B", "__EXTTOCALL=707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-exten-vm:4] Set("SCCP/612-0000000B", "__PICKUPMARK=707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CFU'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CFU/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CFB'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CFB/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-exten-vm:5] Set("SCCP/612-0000000B", "RT=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: pbx_functions.c:608 ast_func_read: Function SIP_HEADER not registered
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-exten-vm:6] ExecIf("SCCP/612-0000000B", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: pbx_functions.c:651 ast_func_read2: Function SIP_HEADER not registered
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: pbx_functions.c:608 ast_func_read: Function SIP_HEADER not registered
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-exten-vm:7] ExecIf("SCCP/612-0000000B", "0?MacroExit()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: pbx_functions.c:651 ast_func_read2: Function SIP_HEADER not registered
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: res_pjsip_header_funcs.c:622 func_read_header: This function requires a PJSIP channel.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-exten-vm:8] ExecIf("SCCP/612-0000000B", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: res_pjsip_header_funcs.c:622 func_read_header: This function requires a PJSIP channel.
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: res_pjsip_header_funcs.c:622 func_read_header: This function requires a PJSIP channel.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-exten-vm:9] ExecIf("SCCP/612-0000000B", "0?MacroExit()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] ERROR[8654][C-00000032]: res_pjsip_header_funcs.c:622 func_read_header: This function requires a PJSIP channel.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Gosub'
    -- Executing [s@macro-exten-vm:10] Gosub("SCCP/612-0000000B", "sub-record-check,s,1(exten,707,dontcare)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:605 gosub_exec: Channel SCCP/612-0000000B has no datastore, so we're allocating one.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:647 gosub_exec: Setting 'ARG1' to 'exten'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:647 gosub_exec: Setting 'ARG2' to '707'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:647 gosub_exec: Setting 'ARG3' to 'dontcare'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Gosub
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:486 _macro_exec: Incrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-record-check:1] GotoIf("SCCP/612-0000000B", "0?initialized") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:2] Set("SCCP/612-0000000B", "__REC_STATUS=INITIALIZED") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:3] Set("SCCP/612-0000000B", "NOW=1650160802") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:4] Set("SCCP/612-0000000B", "__DAY=16") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:5] Set("SCCP/612-0000000B", "__MONTH=04") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:6] Set("SCCP/612-0000000B", "__YEAR=2022") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:7] Set("SCCP/612-0000000B", "__TIMESTR=20220416-220002") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:8] Set("SCCP/612-0000000B", "__FROMEXTEN=unknown") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:9] Set("SCCP/612-0000000B", "__MON_FMT=wav") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-record-check:10] NoOp("SCCP/612-0000000B", "Recordings initialized") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@sub-record-check:11] ExecIf("SCCP/612-0000000B", "0?Set(ARG3=dontcare)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:12] Set("SCCP/612-0000000B", "REC_POLICY_MODE_SAVE=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@sub-record-check:13] ExecIf("SCCP/612-0000000B", "0?Set(REC_STATUS=NO)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '5'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-record-check:14] GotoIf("SCCP/612-0000000B", "5?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-record-check:17] GotoIf("SCCP/612-0000000B", "1?sub-record-check,exten,1") in new stack
    -- Goto (sub-record-check,exten,1)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [exten@sub-record-check:1] NoOp("SCCP/612-0000000B", "Exten Recording Check between unknown and 707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [exten@sub-record-check:2] Set("SCCP/612-0000000B", "CALLTYPE=internal") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [exten@sub-record-check:3] ExecIf("SCCP/612-0000000B", "0?Set(CALLTYPE=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [exten@sub-record-check:4] Set("SCCP/612-0000000B", "CALLEE=force") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [exten@sub-record-check:5] ExecIf("SCCP/612-0000000B", "0?Set(CALLEE=dontcare)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [exten@sub-record-check:6] GotoIf("SCCP/612-0000000B", "0?callee") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [exten@sub-record-check:7] GotoIf("SCCP/612-0000000B", "0?caller") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'unknown/recording/priority' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/unknown/recording/priority not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'unknown/recording/priority' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/unknown/recording/priority not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [exten@sub-record-check:8] ExecIf("SCCP/612-0000000B", "0?Set(CALLER_PRI=):Set(CALLER_PRI=0)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'unknown/recording/priority' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/unknown/recording/priority not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'unknown/recording/priority' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/unknown/recording/priority not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '2'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [exten@sub-record-check:9] ExecIf("SCCP/612-0000000B", "2?Set(CALLEE_PRI=10):Set(CALLEE_PRI=0)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [exten@sub-record-check:10] GotoIf("SCCP/612-0000000B", "0?caller:callee") in new stack
    -- Goto (sub-record-check,exten,11)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Gosub'
    -- Executing [exten@sub-record-check:11] Gosub("SCCP/612-0000000B", "recordcheck,1(force,internal,707)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:647 gosub_exec: Setting 'ARG1' to 'force'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:647 gosub_exec: Setting 'ARG2' to 'internal'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_stack.c:647 gosub_exec: Setting 'ARG3' to '707'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Gosub
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:486 _macro_exec: Incrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [recordcheck@sub-record-check:1] NoOp("SCCP/612-0000000B", "Starting recording check against force") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Goto'
    -- Executing [recordcheck@sub-record-check:2] Goto("SCCP/612-0000000B", "force") in new stack
    -- Goto (sub-record-check,recordcheck,5)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Goto
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [recordcheck@sub-record-check:5] Set("SCCP/612-0000000B", "__REC_POLICY_MODE=FORCE") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [recordcheck@sub-record-check:6] GotoIf("SCCP/612-0000000B", "1?startrec") in new stack
    -- Goto (sub-record-check,recordcheck,16)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [recordcheck@sub-record-check:16] NoOp("SCCP/612-0000000B", "Starting recording: internal, 707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [recordcheck@sub-record-check:17] Set("SCCP/612-0000000B", "__CALLFILENAME=internal-707-unknown-20220416-220002-1650160802.113") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] WARNING[8654][C-00000032]: func_strings.c:1509 function_eval: EVAL requires an argument: EVAL(<string>)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'MixMonitor'
    -- Executing [recordcheck@sub-record-check:18] MixMonitor("SCCP/612-0000000B", "2022/04/16/internal-707-unknown-20220416-220002-1650160802.113.wav,abi(LOCAL_MIXMON_ID),") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: autochan.c:54 ast_autochan_setup: Created autochan 0x7f64580c0080 to hold channel SCCP/612-0000000B (0x273bda0)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: MixMonitor
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [recordcheck@sub-record-check:19] Set("SCCP/612-0000000B", "__MIXMON_ID=0x7f6458096240") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [recordcheck@sub-record-check:20] Set("SCCP/612-0000000B", "__RECORD_ID=SCCP/612-0000000B") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [recordcheck@sub-record-check:21] Set("SCCP/612-0000000B", "__REC_STATUS=RECORDING") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [recordcheck@sub-record-check:22] Set("SCCP/612-0000000B", "CDR(recordingfile)=internal-707-unknown-20220416-220002-1650160802.113.wav") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Return'
    -- Executing [recordcheck@sub-record-check:23] Return("SCCP/612-0000000B", "") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Return
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:507 _macro_exec: Decrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Return'
    -- Executing [exten@sub-record-check:12] Return("SCCP/612-0000000B", "") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Return
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:507 _macro_exec: Decrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-exten-vm:11] GotoIf("SCCP/612-0000000B", "1?macrodial") in new stack
    -- Goto (macro-exten-vm,s,17)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-exten-vm:17] GosubIf("SCCP/612-0000000B", "0?clrheader,1()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Macro'
    -- Executing [s@macro-exten-vm:18] Macro("SCCP/612-0000000B", "dial-one,,HhTtr,707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:1] Set("SCCP/612-0000000B", "DEXTEN=707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:2] Set("SCCP/612-0000000B", "__CRM_SOURCE=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:3] ExecIf("SCCP/612-0000000B", "0?Set(__EXTTOCALL=707)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:4] Set("SCCP/612-0000000B", "DIALSTATUS_CW=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707/screen' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/707/screen not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:5] GosubIf("SCCP/612-0000000B", "0?screen,1()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707/screen' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER/707/screen not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CF'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CF/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:6] GosubIf("SCCP/612-0000000B", "0?cf,1()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CF'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CF/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'DND'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: DND/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:7] GotoIf("SCCP/612-0000000B", "1?skip1") in new stack
    -- Goto (macro-dial-one,s,10)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:10] GotoIf("SCCP/612-0000000B", "0?nodial") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:11] GotoIf("SCCP/612-0000000B", "0?continue") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CW'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CW/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:12] Set("SCCP/612-0000000B", "EXTHASCW=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CFB'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CFB/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CFU'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CFU/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:13] GotoIf("SCCP/612-0000000B", "1?next1:cwinusebusy") in new stack
    -- Goto (macro-dial-one,s,14)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CFU'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CFU/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:14] GotoIf("SCCP/612-0000000B", "0?docfu:skip3") in new stack
    -- Goto (macro-dial-one,s,18)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CFB'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: CFB/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:18] GotoIf("SCCP/612-0000000B", "1?next2:continue") in new stack
    -- Goto (macro-dial-one,s,19)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:19] GotoIf("SCCP/612-0000000B", "1?continue") in new stack
    -- Goto (macro-dial-one,s,27)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:27] GotoIf("SCCP/612-0000000B", "0?nodial") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:28] GosubIf("SCCP/612-0000000B", "1?dstring,1():dlocal,1()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:497 _macro_exec: Incrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:1] Set("SCCP/612-0000000B", "DSTRING=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:2] Set("SCCP/612-0000000B", "DEVICES=707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [dstring@macro-dial-one:3] ExecIf("SCCP/612-0000000B", "0?Return()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [dstring@macro-dial-one:4] ExecIf("SCCP/612-0000000B", "0?Set(DEVICES=07)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:5] Set("SCCP/612-0000000B", "LOOPCNT=1") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:6] Set("SCCP/612-0000000B", "ITER=1") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:7] Set("SCCP/612-0000000B", "THISDIAL=SCCP/707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [dstring@macro-dial-one:8] GotoIf("SCCP/612-0000000B", "1?docheck") in new stack
    -- Goto (macro-dial-one,dstring,14)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [dstring@macro-dial-one:14] GotoIf("SCCP/612-0000000B", "0?skipset") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:15] Set("SCCP/612-0000000B", "DSTRING=SCCP/707&") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '2'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:16] Set("SCCP/612-0000000B", "ITER=2") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [dstring@macro-dial-one:17] GotoIf("SCCP/612-0000000B", "0?begin") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [dstring@macro-dial-one:18] ExecIf("SCCP/612-0000000B", "0?Return()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '8'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [dstring@macro-dial-one:19] Set("SCCP/612-0000000B", "DSTRING=SCCP/707") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Return'
    -- Executing [dstring@macro-dial-one:20] Return("SCCP/612-0000000B", "") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Return
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:507 _macro_exec: Decrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:29] GotoIf("SCCP/612-0000000B", "0?nodial") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:30] GotoIf("SCCP/612-0000000B", "0?skiptrace") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_strings.c:1037 regex: FUNCTION REGEX (^[+]?[0-9]+$)()
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:31] GosubIf("SCCP/612-0000000B", "0?ctset,1():ctclear,1()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_strings.c:1037 regex: FUNCTION REGEX (^[+]?[0-9]+$)()
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:502 _macro_exec: Incrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '707' in family 'CALLTRACE'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:312 function_db_delete: DB_DELETE: CALLTRACE/707 not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [ctclear@macro-dial-one:1] NoOp("SCCP/612-0000000B", "Deleting: CALLTRACE/707 ") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Return'
    -- Executing [ctclear@macro-dial-one:2] Return("SCCP/612-0000000B", "") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Return
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:507 _macro_exec: Decrementing gosub_level
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_strings.c:1037 regex: FUNCTION REGEX ((M[(]auto-blkvm[)]))(HhTtr)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:32] Set("SCCP/612-0000000B", "D_OPTIONS=HhTtr") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:33] GosubIf("SCCP/612-0000000B", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-dial-one:34] NoOp("SCCP/612-0000000B", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Noop
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:35] ExecIf("SCCP/612-0000000B", "0?Set(ALERT_INFO=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:36] ExecIf("SCCP/612-0000000B", "0?Set(ALERT_INFO=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:37] ExecIf("SCCP/612-0000000B", "0?Set(ALERT_INFO=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:38] ExecIf("SCCP/612-0000000B", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:39] ExecIf("SCCP/612-0000000B", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:40] GosubIf("SCCP/612-0000000B", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:41] ExecIf("SCCP/612-0000000B", "0?Set(CHANNEL(musicclass)=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dial-one:42] GosubIf("SCCP/612-0000000B", "0?qwait,1()") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GosubIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:43] Set("SCCP/612-0000000B", "__CWIGNORE=") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dial-one:44] Set("SCCP/612-0000000B", "__KEEPCID=TRUE") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Set
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:45] GotoIf("SCCP/612-0000000B", "0?usegoto,1") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_builtins.c:1319 pbx_builtin_gotoif: Not taking any branch
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key '/cidname' in family 'AMPUSER'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: func_db.c:149 function_db_read: DB: AMPUSER//cidname not found in database.
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dial-one:46] GotoIf("SCCP/612-0000000B", "1?godial") in new stack
    -- Goto (macro-dial-one,s,51)
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Macro'
    -- Executing [s@macro-dial-one:51] Macro("SCCP/612-0000000B", "dialout-one-predial-hook,") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'MacroExit'
    -- Executing [s@macro-dialout-one-predial-hook:1] MacroExit("SCCP/612-0000000B", "") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: Macro
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:52] ExecIf("SCCP/612-0000000B", "0?Set(D_OPTIONS=HhtrI)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dial-one:53] ExecIf("SCCP/612-0000000B", "0?Set(CWRING=r(callwaiting)):Set(CWRING=)") in new stack
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:02] DEBUG[8654][C-00000032]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
  == Begin MixMonitor Recording SCCP/612-0000000B
    -- SCCP: Asterisk request to call SCCP/707-0000000C (dest:707, timeout: 0)
    -- 707: Asterisk request to call SCCP/707-0000000C
    -- SCCP: (sccp_pbx_call) asterisk callerid='Mark x612 <>'
    -- SCCP/707-0000000C: SCCP/707-0000000C : CallInfo:
        |- presentation: CallerId Presentation Allowed

    -- SEP000F34DF0FD3: Getting the active channel on device.
    -- SEP000F34DF0FD3: No active channel on device.
    -- 707: #calls:1, Incoming calls limit:6
    -- SEP000F34DF0FD3: Ringing Line: 707 on device:SEP000F34DF0FD3 using channel:SCCP/707-0000000C, ringermode:Outside
    -- SEP000F34DF0FD3: Indicate SCCP new state:RINGING, current channel state:DOWN on call:SCCP/707-0000000C, lineInstance:2 (previous channelstate:DOWN)
    -- SEP000F34DF0FD3: Found matching ld. Aux parameter =
    -- SEP000F34DF0FD3: Normal ring occurred.
    -- SEP000F34DF0FD3: Finish to indicate channel state:RINGING on call:SCCP/707-0000000C, lineInstance:2. New channel state:RINGING
    -- SCCP/707-0000000C: (sccp_pbx_call) Returning: 0
    -- Called SCCP/707
    -- SCCP: (pbx_indicate) start indicate 'AST_CONTROL_RINGING: Remote end is ringing'
    -- SCCP/612-0000000B: (pbx_indicate) start indicate 'AST_CONTROL_RINGING: Remote end is ringing'
 SEP002D4482438A: (pbx_indicate) start indicate 'AST_CONTROL_RINGING: Remote end is ringing' (3) condition on channel SCCP/612-0000000B (rtp_instance:yes, reception.state:0/No codec, transmission.state:0/No codec)
    -- SEP002D4482438A: Indicate SCCP new state:RINGOUT, current channel state:DIALING on call:SCCP/612-0000000B, lineInstance:1 (previous channelstate:OFFHOOK)
    -- SEP002D4482438A: Finish to indicate channel state:RINGOUT on call:SCCP/612-0000000B, lineInstance:1. New channel state:RINGOUT
  == SEP002D4482438A: (pbx_indicate) finish: send indication (res:0)
    -- SCCP/707-0000000C is ringing
    -- SCCP: (pbx_indicate) start indicate 'AST_CONTROL_RINGING: Remote end is ringing'
    -- SCCP/612-0000000B: (pbx_indicate) start indicate 'AST_CONTROL_RINGING: Remote end is ringing'
 SEP002D4482438A: (pbx_indicate) start indicate 'AST_CONTROL_RINGING: Remote end is ringing' (3) condition on channel SCCP/612-0000000B (rtp_instance:yes, reception.state:0/No codec, transmission.state:0/No codec)
    -- SEP002D4482438A: Indicate SCCP new state:RINGOUT, current channel state:RINGOUT on call:SCCP/612-0000000B, lineInstance:1 (previous channelstate:DIALING)
    -- SEP002D4482438A: Finish to indicate channel state:RINGOUT on call:SCCP/612-0000000B, lineInstance:1. New channel state:RINGOUT
  == SEP002D4482438A: (pbx_indicate) finish: send indication (res:0)
[2022-04-16 22:00:02] DEBUG[2597]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[2597]: db.c:392 db_get_common: Unable to find key 'DND612' in family 'CustomDevstate'
[2022-04-16 22:00:02] DEBUG[8673]: manager.c:6678 process_message: Running action 'Login'
[2022-04-16 22:00:02] DEBUG[8688]: manager.c:6678 process_message: Running action 'Login'
[2022-04-16 22:00:03] DEBUG[8704]: manager.c:6678 process_message: Running action 'Login'
[2022-04-16 22:00:03] DEBUG[8718]: manager.c:6678 process_message: Running action 'Login'
[2022-04-16 22:00:12] DEBUG[5456]: res_pjsip_session.c:4236 session_on_rx_request:  (null session) Request: PUBLISH
[2022-04-16 22:00:12] DEBUG[5456]: res_pjsip_session.c:4256 session_on_rx_request:  (null session) Handled request PUBLISH  ? no
[2022-04-16 22:00:12] WARNING[5456]: res_pjsip_pubsub.c:3384 pubsub_on_rx_publish_request: No registered publish handler for event presence from 201
    -- SCCP/612-0000000B: Disabling scheduler / Removing Scheduled tasks (digittimeout_id:-1) (hangup_id:-1) (cfwd_noanswer_id:-1)
  == SEP002D4482438A: Ending call SCCP/612-0000000B (state:RINGOUT)
    -- SEP002D4482438A: Sending hangupRequest to Call SCCP/612-0000000B (state: RINGOUT)
SCCP/612-0000000B: (RequestQueueHangup): Hangup Queued
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: channel.c:2550 ast_hangup: Channel 0x7f64580eb090 'SCCP/707-0000000C' hanging up.  Refs: 3
    -- SCCP/707-0000000C: Asked to hangup channel.
    -- SCCP/707-0000000C: Current pbxchannelstate RINGING(22)
    -- SEP000A36BE05A1: Indicate SCCP new state:ONHOOK, current channel state:RINGING on call:SCCP/707-0000000C, lineInstance:2 (previous channelstate:RINGING)
    -- SEP000A36BE05A1: Finish to indicate channel state:ONHOOK on call:SCCP/707-0000000C, lineInstance:2. New channel state:DOWN
    -- SCCP: Cleaning channel SCCP/707-0000000C
    -- SCCP/707-0000000C: Disabling scheduler / Removing Scheduled tasks (digittimeout_id:-1) (hangup_id:-1) (cfwd_noanswer_id:-1)
[2022-04-16 22:00:16] DEBUG[2603]: cdr.c:1483 cdr_object_finalize: Finalized CDR for SCCP/612-0000000B - start 1650160802.108161 answer 0.000000 end 1650160816.003661 dur 13.895 bill 1650160816.003 dispo NO ANSWER
[2022-04-16 22:00:16] DEBUG[2597]: db.c:392 db_get_common: Unable to find key 'DND707' in family 'CustomDevstate'
    -- Destroying channel SCCP/707-0000000C
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: channel.c:2196 ast_channel_destructor: Channel 0x7f64580eb090 'SCCP/707-0000000C' destroying
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: stasis.c:451 topic_dtor: Topic 'channel:1650160802.114': 0x7f64580af0e0 destroyed
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: app_dial.c:3429 dial_exec_full: Exiting with DIALSTATUS=CANCEL.
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: app_dial.c:3460 dial_exec_full:  SCCP/612-0000000B: Done
  == Spawn extension (macro-dial-one, s, 56) exited non-zero on 'SCCP/612-0000000B' in macro 'dial-one'
  == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SCCP/612-0000000B' in macro 'exten-vm'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx.c:4435 __ast_pbx_run: Spawn extension (ext-local,707,3) exited non-zero on 'SCCP/612-0000000B'
  == Spawn extension (ext-local, 707, 3) exited non-zero on 'SCCP/612-0000000B'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: channel.c:2459 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SCCP/612-0000000B'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: channel.c:2459 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'SCCP/612-0000000B'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Macro'
    -- Executing [h@ext-local:1] Macro("SCCP/612-0000000B", "hangupcall,") in new stack
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '1'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-hangupcall:1] GotoIf("SCCP/612-0000000B", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: GotoIf
[2022-04-16 22:00:16] DEBUG[2603]: cdr.c:1483 cdr_object_finalize: Finalized CDR for SCCP/707-0000000C - start 1650160802.201790 answer 0.000000 end 1650160816.007200 dur 13.805 bill 1650160816.007 dispo NO ANSWER
[2022-04-16 22:00:16] DEBUG[2603]: cdr.c:1314 cdr_object_create_public_records: CDR for SCCP/707-0000000C is dialed and has no Party B; discarding
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx_variables.c:840 pbx_substitute_variables_helper_full_location: Expression result is '0'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-hangupcall:3] ExecIf("SCCP/612-0000000B", "0?Set(CDR(recordingfile)=)") in new stack
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: app_macro.c:482 _macro_exec: Executed application: ExecIf
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx.c:2936 pbx_extension_helper: Launching 'Hangup'
    -- Executing [s@macro-hangupcall:4] Hangup("SCCP/612-0000000B", "") in new stack
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: channel.c:2459 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'SCCP/612-0000000B'
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SCCP/612-0000000B' in macro 'hangupcall'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: pbx.c:4247 ast_pbx_h_exten_run: Spawn extension (ext-local,h,1) exited non-zero on 'SCCP/612-0000000B'
  == Spawn extension (ext-local, h, 1) exited non-zero on 'SCCP/612-0000000B'
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: channel.c:2550 ast_hangup: Channel 0x273bda0 'SCCP/612-0000000B' hanging up.  Refs: 4
    -- SCCP/612-0000000B: Asked to hangup channel.
    -- SCCP/612-0000000B: Current pbxchannelstate RINGOUT(20)
    -- SEP002D4482438A: Indicate SCCP new state:ONHOOK, current channel state:RINGOUT on call:SCCP/612-0000000B, lineInstance:1 (previous channelstate:RINGOUT)
    -- SEP002D4482438A: Finish to indicate channel state:ONHOOK on call:SCCP/612-0000000B, lineInstance:1. New channel state:DOWN
    -- SEP002D4482438A: Device is Requesting Connections Statistics And Clear
    -- SCCP: Cleaning channel SCCP/612-0000000B
    -- SEP002D4482438A: Set the active channel 0 on device
    -- SEP002D4482438A: Looking for selected channel (11)
[2022-04-16 22:00:16] DEBUG[2597]: db.c:392 db_get_common: Unable to find key 'DND612' in family 'CustomDevstate'
    -- Destroying channel SCCP/612-0000000B
[2022-04-16 22:00:16] DEBUG[8654][C-00000032]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x2067820'
[2022-04-16 22:00:16] DEBUG[8656][C-00000032]: autochan.c:72 ast_autochan_destroy: Removed autochan 0x7f64580c0080 from the list, about to free it
[2022-04-16 22:00:16] DEBUG[8656][C-00000032]: channel.c:2196 ast_channel_destructor: Channel 0x273bda0 'SCCP/612-0000000B' destroying
[2022-04-16 22:00:16] DEBUG[8656][C-00000032]: stasis.c:451 topic_dtor: Topic 'channel:1650160802.113': 0x24e0270 destroyed
  == MixMonitor close filestream (mixed)
  == End MixMonitor Recording SCCP/612-0000000B
    -- QualityStats: MLQK=0.0000;MLQKav=0.0000;MLQKmn=0.0000;MLQKmx=0.0000;ICR=0.0143;CCR=0.0143;ICRmx=0.0143;CS=1;SCS=0;MLQKvr=0.95
    -- SEP002D4482438A: Call Statistics:
       [
         Last Call        : CallID: 11 Packets sent: 180 rcvd: 159 lost: 0 jitter: 9 latency: 0
         Last Quality     : MLQK=0.0000;MLQKav=0.0000;MLQKmn=0.0000;MLQKmx=0.0000;MLQKvr=0.95|ICR=0.0143;CCR=0.0143;ICRmx=0.0143|CS=1;SCS=0
         Mean Statistics  : #Calls: 6 Packets sent: 180 rcvd: 159 lost: 0 jitter: 9 latency: 0
         Mean Quality     : MLQK=0.0000;MLQKav=0.0000;MLQKmn=0.0000;MLQKmx=0.0000;MLQKvr=0.95|ICR=0.0143;CCR=0.0143;ICRmx=0.0143|CS=1;SCS=0
       ]
[2022-04-16 22:00:35] DEBUG[8739]: manager.c:6678 process_message: Running action 'Login'
[2022-04-16 22:00:36] WARNING[8085]: res_musiconhold.c:809 monmp3thread: poll() failed: Interrupted system call
[2022-04-16 22:00:40] DEBUG[8085]: res_musiconhold.c:849 monmp3thread: Read 380 bytes of audio while expecting 640
[2022-04-16 22:00:43] DEBUG[8638]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dkgroot dkgroot

@steve-lad steve-lad

Labels
question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@dkgroot @mbielech5 @steve-lad @samam9911