Paging and intercomm Broken since module updates

After some module updates on a FreePBX13 system, Pagin and intercomm are no longer working properly. When dialing the intercom group the phones ring instead of beep and go offhook.

I’ve now seen this on two systems. The first I couldn’t find a cause so I just re-loaded it from scratch. Now I have a second with the same isssue so I’d like to figure out what’s causing it.

I tried rolling back the paging and intercomm module but that didn’t fix it.

are there any current known issues?

found it… rolled back the core module and paging and intercomm returned…

1 Like

If you can reproduce it, please report this on the bug tracker issues.freepbx.org

I am pretty sure this is fixed in the edge version of core.

2 Likes

We have the same issue. It actually also breaks our custom alert from trunks to digium phones. They do not ring as they’re configured to. I tried the latest edge core module today. Not fixed. Everything had been working great for a couple years until we updated the Core Module recently. We rolled back to 14.0.18.41 and issue has gone away with auto-answer, intercom, and our custom alert info all acting as intended and working properly.

I’m not familiar enough with FreePBX to troubleshoot, but it’s definitely tied to core module updates after 18.41. I reported this as a bug but it was just closed as not repeatable. I can repeat this on our end.

FreePBX 14

Wanted to have a certain ringtone play when a specific caller ID called in.

Created an alert in the Digium Phones module

Created a custom ringtone and assigned it to the alert and also phone in the Digium Phones module

Created an inbound route for the DID with CID specified, set the alert and directed calls to a specific extension. Phone on the extension is a Digium D60 firmware 2.7.2

As a test I set the custom ringtone as the default ringtone for the phone then initiated a test call. The ringtone worked.

Removed the default ringtone and reconfigured the phone.

Dialed in to see if the alert would play the specified ringtone. It did not. The alert information is in the asterisk logs but no matter what I try I can’t get the ringtone to play from the alert.

Is this a known bug, is this functionality not possible with FreePBX and Digium phones or have a mis-configured something?

Test call logs showing the alert (note I redacted the last for digits of all phone numbers):

[2019-02-26 13:57:21] VERBOSE[10077][C-000001ef] netsock2.c: Using SIP RTP TOS bits 184
[2019-02-26 13:57:21] VERBOSE[10077][C-000001ef] netsock2.c: Using SIP RTP CoS mark 5
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk-sip-VI_70:1] Set("SIP/VI_70-00000297", "GROUP()=OUT_4") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk-sip-VI_70:2] Goto("SIP/VI_70-00000297", "from-trunk,973453XXXX,1") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (from-trunk,973453XXXX,1)
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:1] Set("SIP/VI_70-00000297", "__DIRECTION=INBOUND") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:2] Gosub("SIP/VI_70-00000297", "sub-record-check,s,1(in,973453XXXX,dontcare)") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/VI_70-00000297", "0?initialized") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:2] Set("SIP/VI_70-00000297", "__REC_STATUS=INITIALIZED") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:3] Set("SIP/VI_70-00000297", "NOW=1551207441") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:4] Set("SIP/VI_70-00000297", "__DAY=26") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:5] Set("SIP/VI_70-00000297", "__MONTH=02") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:6] Set("SIP/VI_70-00000297", "__YEAR=2019") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:7] Set("SIP/VI_70-00000297", "__TIMESTR=20190226-135721") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:8] Set("SIP/VI_70-00000297", "__FROMEXTEN=unknown") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:9] Set("SIP/VI_70-00000297", "__MON_FMT=wav") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/VI_70-00000297", "Recordings initialized") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/VI_70-00000297", "0?Set(ARG3=dontcare)") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:12] Set("SIP/VI_70-00000297", "REC_POLICY_MODE_SAVE=") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/VI_70-00000297", "0?Set(REC_STATUS=NO)") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/VI_70-00000297", "2?checkaction") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/VI_70-00000297", "1?sub-record-check,in,1") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/VI_70-00000297", "Inbound Recording Check to 973453XXXX") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [in@sub-record-check:2] Set("SIP/VI_70-00000297", "FROMEXTEN=unknown") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/VI_70-00000297", "11?Set(FROMEXTEN=1973886XXXX)") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/VI_70-00000297", "recordcheck,1(dontcare,in,973453XXXX)") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/VI_70-00000297", "Starting recording check against dontcare") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/VI_70-00000297", "dontcare") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/VI_70-00000297", "") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [in@sub-record-check:5] Return("SIP/VI_70-00000297", "") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:3] Set("SIP/VI_70-00000297", "CHANNEL(tonezone)=us") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:4] Set("SIP/VI_70-00000297", "__FROM_DID=973453XXXX") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:5] Set("SIP/VI_70-00000297", "returnhere=1") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:6] Gosub("SIP/VI_70-00000297", "app-blacklist-check,s,1()") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/VI_70-00000297", "0?blacklisted") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/VI_70-00000297", "CALLED_BLACKLIST=1") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/VI_70-00000297", "") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:7] Set("SIP/VI_70-00000297", "CDR(did)=973453XXXX") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:8] GotoIf("SIP/VI_70-00000297", "0?") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:9] ExecIf("SIP/VI_70-00000297", "1 ?Set(CALLERID(name)=1973886XXXX)") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:10] Set("SIP/VI_70-00000297", "__MOHCLASS=") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:11] Set("SIP/VI_70-00000297", "__REVERSAL_REJECT=FALSE") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:12] GotoIf("SIP/VI_70-00000297", "1?post-reverse-charge") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (from-trunk,973453XXXX,14)
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:14] NoOp("SIP/VI_70-00000297", "") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:15] Set("SIP/VI_70-00000297", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:16] Set("SIP/VI_70-00000297", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:17] Set("SIP/VI_70-00000297", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:18] Set("SIP/VI_70-00000297", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:19] Set("SIP/VI_70-00000297", "__ALERT_INFO=Batman") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:20] Set("SIP/VI_70-00000297", "__RVOL=14") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:21] NoOp("SIP/VI_70-00000297", "CallerID Entry Point") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [973453XXXX@from-trunk:22] Goto("SIP/VI_70-00000297", "from-did-direct,207,1") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (from-did-direct,207,1)
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx.c: Executing [207@from-did-direct:1] GotoIf("SIP/VI_70-00000297", "1?ext-local,207,1:followme-check,207,1") in new stack
[2019-02-26 13:57:21] VERBOSE[25715][C-000001ef] pbx_builtins.c: Goto (ext-local,207,1)

We had a very similar issue with our digium D70. Everything had been working great for a couple years until we updated the Core Module recently. Some other user made a mention they had isolated it to a core module update for them as well. We rolled back to 14.0.18.41 and issue has gone away with auto-answer, intercom, and our custom alert info all acting as intended and originally configured.

You need to post the FULL log. Not a subset that you think is fine.

I tried, forum character limitation prevented it so I truncated it to show that indeed the alert was being sent.

[2019-02-28 06:29:24] VERBOSE[16084] asterisk.c: Remote UNIX connection disconnected
[2019-02-28 06:29:38] VERBOSE[10077][C-000001f8] netsock2.c: Using SIP RTP TOS bits 184
[2019-02-28 06:29:38] VERBOSE[10077][C-000001f8] netsock2.c: Using SIP RTP CoS mark 5
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk-sip-VI_31:1] Set("SIP/VI_31-000002a5", "GROUP()=OUT_2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk-sip-VI_31:2] Goto("SIP/VI_31-000002a5", "from-trunk,973453XXXX,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (from-trunk,973453XXXX,1)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:1] Set("SIP/VI_31-000002a5", "__DIRECTION=INBOUND") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:2] Gosub("SIP/VI_31-000002a5", "sub-record-check,s,1(in,973453XXXX,dontcare)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/VI_31-000002a5", "0?initialized") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:2] Set("SIP/VI_31-000002a5", "__REC_STATUS=INITIALIZED") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:3] Set("SIP/VI_31-000002a5", "NOW=1551353378") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:4] Set("SIP/VI_31-000002a5", "__DAY=28") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:5] Set("SIP/VI_31-000002a5", "__MONTH=02") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:6] Set("SIP/VI_31-000002a5", "__YEAR=2019") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:7] Set("SIP/VI_31-000002a5", "__TIMESTR=20190228-062938") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:8] Set("SIP/VI_31-000002a5", "__FROMEXTEN=unknown") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:9] Set("SIP/VI_31-000002a5", "__MON_FMT=wav") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/VI_31-000002a5", "Recordings initialized") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/VI_31-000002a5", "0?Set(ARG3=dontcare)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:12] Set("SIP/VI_31-000002a5", "REC_POLICY_MODE_SAVE=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/VI_31-000002a5", "0?Set(REC_STATUS=NO)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/VI_31-000002a5", "2?checkaction") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/VI_31-000002a5", "1?sub-record-check,in,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/VI_31-000002a5", "Inbound Recording Check to 973453XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [in@sub-record-check:2] Set("SIP/VI_31-000002a5", "FROMEXTEN=unknown") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/VI_31-000002a5", "11?Set(FROMEXTEN=1973886XXXX)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/VI_31-000002a5", "recordcheck,1(dontcare,in,973453XXXX)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/VI_31-000002a5", "Starting recording check against dontcare") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/VI_31-000002a5", "dontcare") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [in@sub-record-check:5] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:3] Set("SIP/VI_31-000002a5", "CHANNEL(tonezone)=us") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:4] Set("SIP/VI_31-000002a5", "__FROM_DID=973453XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:5] Set("SIP/VI_31-000002a5", "returnhere=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:6] Gosub("SIP/VI_31-000002a5", "app-blacklist-check,s,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/VI_31-000002a5", "0?blacklisted") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/VI_31-000002a5", "CALLED_BLACKLIST=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:7] Set("SIP/VI_31-000002a5", "CDR(did)=973453XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:8] GotoIf("SIP/VI_31-000002a5", "0?") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:9] ExecIf("SIP/VI_31-000002a5", "1 ?Set(CALLERID(name)=1973886XXXX)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:10] Set("SIP/VI_31-000002a5", "__MOHCLASS=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:11] Set("SIP/VI_31-000002a5", "__REVERSAL_REJECT=FALSE") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:12] GotoIf("SIP/VI_31-000002a5", "1?post-reverse-charge") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (from-trunk,973453XXXX,14)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:14] NoOp("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:15] Set("SIP/VI_31-000002a5", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:16] Set("SIP/VI_31-000002a5", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:17] Set("SIP/VI_31-000002a5", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:18] Set("SIP/VI_31-000002a5", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:19] Set("SIP/VI_31-000002a5", "__ALERT_INFO=Batman") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:20] Set("SIP/VI_31-000002a5", "__RVOL=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:21] NoOp("SIP/VI_31-000002a5", "CallerID Entry Point") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [973453XXXX@from-trunk:22] Goto("SIP/VI_31-000002a5", "from-did-direct,207,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (from-did-direct,207,1)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [207@from-did-direct:1] GotoIf("SIP/VI_31-000002a5", "1?ext-local,207,1:followme-check,207,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (ext-local,207,1)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [207@ext-local:1] Set("SIP/VI_31-000002a5", "__RINGTIMER=15") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [207@ext-local:2] Macro("SIP/VI_31-000002a5", "exten-vm,207,207,0,0,0") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:1] Macro("SIP/VI_31-000002a5", "user-callerid,") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/VI_31-000002a5", "TOUCH_MONITOR=1551353378.1565") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/VI_31-000002a5", "AMPUSER=1973886XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/VI_31-000002a5", "0?report") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/VI_31-000002a5", "1?Set(REALCALLERIDNUM=1973886XXXX)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/VI_31-000002a5", "AMPUSER=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/VI_31-000002a5", "0?limit") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/VI_31-000002a5", "AMPUSERCIDNAME=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/VI_31-000002a5", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/VI_31-000002a5", "1?report") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-user-callerid,s,16)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/VI_31-000002a5", "Macro Depth is 2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/VI_31-000002a5", "1?report2:macroerror") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/VI_31-000002a5", "0?continue") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("SIP/VI_31-000002a5", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:20] Set("SIP/VI_31-000002a5", "__TTL=64") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("SIP/VI_31-000002a5", "1?continue") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/VI_31-000002a5", "CALLERID(number)=1973886XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/VI_31-000002a5", "CALLERID(name)=1973886XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("SIP/VI_31-000002a5", "0?cnum") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/VI_31-000002a5", "CDR(cnam)=1973886XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/VI_31-000002a5", "CDR(cnum)=1973886XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/VI_31-000002a5", "CHANNEL(language)=en") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:2] Set("SIP/VI_31-000002a5", "RingGroupMethod=none") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:3] Set("SIP/VI_31-000002a5", "__EXTTOCALL=207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:4] Set("SIP/VI_31-000002a5", "__PICKUPMARK=207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:5] Set("SIP/VI_31-000002a5", "RT=15") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("SIP/VI_31-000002a5", "0?Macro(vm,207,DIRECTDIAL,)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("SIP/VI_31-000002a5", "0?MacroExit()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("SIP/VI_31-000002a5", "0?Gosub(ext-intercom,*80207,1())") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("SIP/VI_31-000002a5", "0?MacroExit()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("SIP/VI_31-000002a5", "0?ChanSpy(SIP/207,q)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("SIP/VI_31-000002a5", "0?MacroExit()") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:12] ExecIf("SIP/VI_31-000002a5", "0?Macro(vm,207,DIRECTDIAL,)") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:13] ExecIf("SIP/VI_31-000002a5", "0?MacroExit()") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:14] ExecIf("SIP/VI_31-000002a5", "0?Gosub(ext-intercom,*80207,1())") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:15] ExecIf("SIP/VI_31-000002a5", "0?MacroExit()") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:16] ExecIf("SIP/VI_31-000002a5", "0?ChanSpy(SIP/207,q)") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:17] ExecIf("SIP/VI_31-000002a5", "0?MacroExit()") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:18] Gosub("SIP/VI_31-000002a5", "sub-record-check,s,1(exten,207,dontcare)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/VI_31-000002a5", "11?initialized") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,s,10)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/VI_31-000002a5", "Recordings initialized") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/VI_31-000002a5", "0?Set(ARG3=dontcare)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:12] Set("SIP/VI_31-000002a5", "REC_POLICY_MODE_SAVE=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/VI_31-000002a5", "0?Set(REC_STATUS=NO)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/VI_31-000002a5", "5?checkaction") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/VI_31-000002a5", "1?sub-record-check,exten,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:1] NoOp("SIP/VI_31-000002a5", "Exten Recording Check between 1973886XXXX and 207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:2] Set("SIP/VI_31-000002a5", "CALLTYPE=external") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/VI_31-000002a5", "0?Set(CALLTYPE=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/VI_31-000002a5", "CALLEE=dontcare") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:5] ExecIf("SIP/VI_31-000002a5", "0?Set(CALLEE=dontcare)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:6] GotoIf("SIP/VI_31-000002a5", "1?callee") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,exten,11)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:11] Gosub("SIP/VI_31-000002a5", "recordcheck,1(dontcare,external,207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/VI_31-000002a5", "Starting recording check against dontcare") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/VI_31-000002a5", "dontcare") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [exten@sub-record-check:12] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:19] GotoIf("SIP/VI_31-000002a5", "1?macrodial") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-exten-vm,s,25)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:25] GosubIf("SIP/VI_31-000002a5", "0?clrheader,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-exten-vm:26] Macro("SIP/VI_31-000002a5", "dial-one,15,HhTtr,207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:1] Set("SIP/VI_31-000002a5", "DEXTEN=207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:2] UserEvent("SIP/VI_31-000002a5", "zulu-inbound-call,type:macro-dial-one,from:1973886XXXX,to:207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:3] ExecIf("SIP/VI_31-000002a5", "0?Set(__EXTTOCALL=207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:4] Set("SIP/VI_31-000002a5", "DIALSTATUS_CW=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:5] GosubIf("SIP/VI_31-000002a5", "0?screen,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:6] GosubIf("SIP/VI_31-000002a5", "0?cf,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:7] GotoIf("SIP/VI_31-000002a5", "1?skip1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:10] GotoIf("SIP/VI_31-000002a5", "0?nodial") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:11] GotoIf("SIP/VI_31-000002a5", "0?continue") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:12] Set("SIP/VI_31-000002a5", "EXTHASCW=ENABLED") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:13] GotoIf("SIP/VI_31-000002a5", "0?next1:cwinusebusy") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:25] GotoIf("SIP/VI_31-000002a5", "0?next3:continue") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:27] GotoIf("SIP/VI_31-000002a5", "0?nodial") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:28] GosubIf("SIP/VI_31-000002a5", "1?dstring,1():dlocal,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:1] Set("SIP/VI_31-000002a5", "DSTRING=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:2] Set("SIP/VI_31-000002a5", "DEVICES=207&90207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("SIP/VI_31-000002a5", "0?Return()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("SIP/VI_31-000002a5", "0?Set(DEVICES=07&90207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:5] Set("SIP/VI_31-000002a5", "LOOPCNT=2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:6] Set("SIP/VI_31-000002a5", "ITER=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:7] Set("SIP/VI_31-000002a5", "THISDIAL=SIP/207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("SIP/VI_31-000002a5", "1?zap2dahdi,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/VI_31-000002a5", "0?Return()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("SIP/VI_31-000002a5", "NEWDIAL=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("SIP/VI_31-000002a5", "LOOPCNT2=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("SIP/VI_31-000002a5", "ITER2=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("SIP/VI_31-000002a5", "THISPART2=SIP/207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/VI_31-000002a5", "0?Set(THISPART2=DAHDI/207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("SIP/VI_31-000002a5", "NEWDIAL=SIP/207&") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("SIP/VI_31-000002a5", "ITER2=2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/VI_31-000002a5", "0?begin2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("SIP/VI_31-000002a5", "THISDIAL=SIP/207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("SIP/VI_31-000002a5", "1?docheck") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,dstring,15)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("SIP/VI_31-000002a5", "0?skipset") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:16] Set("SIP/VI_31-000002a5", "DSTRING=SIP/207&") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:17] Set("SIP/VI_31-000002a5", "ITER=2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("SIP/VI_31-000002a5", "1?begin") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,dstring,7)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:7] Set("SIP/VI_31-000002a5", "THISDIAL=PJSIP/90207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("SIP/VI_31-000002a5", "1?zap2dahdi,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/VI_31-000002a5", "0?Return()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("SIP/VI_31-000002a5", "NEWDIAL=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("SIP/VI_31-000002a5", "LOOPCNT2=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("SIP/VI_31-000002a5", "ITER2=1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("SIP/VI_31-000002a5", "THISPART2=PJSIP/90207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/VI_31-000002a5", "0?Set(THISPART2=DAHDIIP/90207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("SIP/VI_31-000002a5", "NEWDIAL=PJSIP/90207&") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("SIP/VI_31-000002a5", "ITER2=2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/VI_31-000002a5", "0?begin2") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("SIP/VI_31-000002a5", "THISDIAL=PJSIP/90207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("SIP/VI_31-000002a5", "0?docheck") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:10] NoOp("SIP/VI_31-000002a5", "Debug: Found PJSIP Destination PJSIP/90207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:11] GotoIf("SIP/VI_31-000002a5", "0?doset") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:12] NoOp("SIP/VI_31-000002a5", "Debug: Updating PJSIP Destination with PJSIP_DIAL_CONTACTS") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:13] Set("SIP/VI_31-000002a5", "THISDIAL=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:14] ExecIf("SIP/VI_31-000002a5", "1?Set(DIALSTATUS=CHANUNAVAIL)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("SIP/VI_31-000002a5", "1?skipset") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,dstring,17)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:17] Set("SIP/VI_31-000002a5", "ITER=3") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("SIP/VI_31-000002a5", "0?begin") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:19] ExecIf("SIP/VI_31-000002a5", "0?Return()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:20] Set("SIP/VI_31-000002a5", "DSTRING=SIP/207") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [dstring@macro-dial-one:21] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:29] GotoIf("SIP/VI_31-000002a5", "0?nodial") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:30] GotoIf("SIP/VI_31-000002a5", "0?skiptrace") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:31] GosubIf("SIP/VI_31-000002a5", "1?ctset,1():ctclear,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [ctset@macro-dial-one:1] Set("SIP/VI_31-000002a5", "DB(CALLTRACE/207)=1973886XXXX") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [ctset@macro-dial-one:2] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:32] Set("SIP/VI_31-000002a5", "D_OPTIONS=HhTtr") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:33] GosubIf("SIP/VI_31-000002a5", "1?func-set-sipheader,s,1(Alert-Info,Batman)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-set-sipheader:1] NoOp("SIP/VI_31-000002a5", "Sip Add Header function called. Adding Alert-Info = Batman") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-set-sipheader:2] Set("SIP/VI_31-000002a5", "HASH(_SIPHEADERS,Alert-Info)=Batman") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-set-sipheader:3] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:34] NoOp("SIP/VI_31-000002a5", "Blind Transfer: , Attended Transfer: , User: , Alert Info: Batman") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:35] ExecIf("SIP/VI_31-000002a5", "0?Set(ALERT_INFO=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:36] ExecIf("SIP/VI_31-000002a5", "0?Set(ALERT_INFO=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:37] ExecIf("SIP/VI_31-000002a5", "0?Set(ALERT_INFO=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:38] ExecIf("SIP/VI_31-000002a5", "1?Set(ALERT_INFO=Batman;volume=14)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:39] ExecIf("SIP/VI_31-000002a5", "0?Set(ALERT_INFO=Batman;volume=14;volume=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:40] GosubIf("SIP/VI_31-000002a5", "1?func-set-sipheader,s,1(Alert-Info,Batman;volume=14)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-set-sipheader:1] NoOp("SIP/VI_31-000002a5", "Sip Add Header function called. Adding Alert-Info = Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-set-sipheader:2] Set("SIP/VI_31-000002a5", "HASH(_SIPHEADERS,Alert-Info)=Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-set-sipheader:3] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:41] ExecIf("SIP/VI_31-000002a5", "0?Set(CHANNEL(musicclass)=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:42] GosubIf("SIP/VI_31-000002a5", "0?qwait,1()") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:43] Set("SIP/VI_31-000002a5", "__CWIGNORE=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:44] Set("SIP/VI_31-000002a5", "__KEEPCID=TRUE") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:45] GotoIf("SIP/VI_31-000002a5", "0?usegoto,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:46] GotoIf("SIP/VI_31-000002a5", "1?godial") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-dial-one,s,51)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:51] Macro("SIP/VI_31-000002a5", "dialout-one-predial-hook,") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:52] ExecIf("SIP/VI_31-000002a5", "1?Set(D_OPTIONS=HhtrI)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:53] Gosub("SIP/VI_31-000002a5", "zulu-user-settings-map,s,1(207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@zulu-user-settings-map:1] GotoIf("SIP/VI_31-000002a5", "0?207,1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@zulu-user-settings-map:2] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:54] Gosub("SIP/VI_31-000002a5", "zulu-send-event,s,1(207,1973886XXXX,207)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@zulu-send-event:1] GotoIf("SIP/VI_31-000002a5", "1?skippopup") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (zulu-send-event,s,4)
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@zulu-send-event:4] NoOp("SIP/VI_31-000002a5", "No Call Pop") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@zulu-send-event:5] UserEvent("SIP/VI_31-000002a5", "zulu-call,eventtype:calling,extension:207,type:,url:,cnam:1973886XXXX,cnum:1973886XXXX,lid:1551353378.1565,from:1973886XXXX,to:207}") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@zulu-send-event:6] Return("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:55] NoOp("SIP/VI_31-000002a5", "Finished") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:56] Set("SIP/VI_31-000002a5", "_zuludialopts=") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:57] AGI("SIP/VI_31-000002a5", "zulureplace-one.agi,DSTRING,90") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/zulureplace-one.agi
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] res_agi.c: zulureplace-one.agi,DSTRING,90: DIALSTRING: SIP/207
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] res_agi.c: zulureplace-one.agi,DSTRING,90: DIALOPTS: HhtrI
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] res_agi.c: zulureplace-one.agi,DSTRING,90: TIMEOUT: 15
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] res_agi.c: zulureplace-one.agi,DSTRING,90: NEWDIALSTRING: SIP/207&Local/90207@zulu-mobile-phone-wait&Local/90207@zulu-mobile-phone-registered&Local/90207@zulu-desktop-phone
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] res_agi.c: <SIP/VI_31-000002a5>AGI Script zulureplace-one.agi completed, returning 0
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:58] NoOp("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:59] ExecIf("SIP/VI_31-000002a5", "0?Set(D_OPTIONS=HhtrIg)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-dial-one:60] Dial("SIP/VI_31-000002a5", "SIP/207&Local/90207@zulu-mobile-phone-wait&Local/90207@zulu-mobile-phone-registered&Local/90207@zulu-desktop-phone,15,HhtrIb(func-apply-sipheaders^s^1)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] netsock2.c: Using SIP RTP TOS bits 184
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] netsock2.c: Using SIP RTP CoS mark 5
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: SIP/207-000002a6 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:1] UserEvent("SIP/207-000002a6", "zulu-call-b,type:func-apply-sipheaders,to:207,from:") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("SIP/207-000002a6", "Applying SIP Headers to channel") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:3] Set("SIP/207-000002a6", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:4] ExecIf("SIP/207-000002a6", "0?Set(Rheader=1)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("SIP/207-000002a6", "1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:6] Set("SIP/207-000002a6", "sipheader=Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:7] SIPAddHeader("SIP/207-000002a6", "Alert-Info: Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:8] Set("SIP/207-000002a6", "PJSIP_HEADER(add,Alert-Info)=Batman;volume=14") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:9] EndWhile("SIP/207-000002a6", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("SIP/207-000002a6", "0") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("SIP/207-000002a6", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("SIP/207-000002a6", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:12] Return("SIP/207-000002a6", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Spawn extension (from-internal, 207, 1) exited non-zero on 'SIP/207-000002a6'
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: SIP/207-000002a6 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Local/90207@zulu-mobile-phone-wait-0000010a;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:1] UserEvent("Local/90207@zulu-mobile-phone-wait-0000010a;1", "zulu-call-b,type:func-apply-sipheaders,to:207,from:") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("Local/90207@zulu-mobile-phone-wait-0000010a;1", "Applying SIP Headers to channel") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:3] Set("Local/90207@zulu-mobile-phone-wait-0000010a;1", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:4] ExecIf("Local/90207@zulu-mobile-phone-wait-0000010a;1", "0?Set(Rheader=1)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90207@zulu-mobile-phone-wait-0000010a;1", "1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:6] Set("Local/90207@zulu-mobile-phone-wait-0000010a;1", "sipheader=Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:7] SIPAddHeader("Local/90207@zulu-mobile-phone-wait-0000010a;1", "Alert-Info: Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:8] Set("Local/90207@zulu-mobile-phone-wait-0000010a;1", "PJSIP_HEADER(add,Alert-Info)=Batman;volume=14") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:9] EndWhile("Local/90207@zulu-mobile-phone-wait-0000010a;1", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90207@zulu-mobile-phone-wait-0000010a;1", "0") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("Local/90207@zulu-mobile-phone-wait-0000010a;1", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("Local/90207@zulu-mobile-phone-wait-0000010a;1", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:12] Return("Local/90207@zulu-mobile-phone-wait-0000010a;1", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Spawn extension (zulu-mobile-phone-wait, 207, 1) exited non-zero on 'Local/90207@zulu-mobile-phone-wait-0000010a;1'
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Local/90207@zulu-mobile-phone-wait-0000010a;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Local/90207@zulu-mobile-phone-registered-0000010b;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:1] UserEvent("Local/90207@zulu-mobile-phone-registered-0000010b;1", "zulu-call-b,type:func-apply-sipheaders,to:207,from:") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("Local/90207@zulu-mobile-phone-registered-0000010b;1", "Applying SIP Headers to channel") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:3] Set("Local/90207@zulu-mobile-phone-registered-0000010b;1", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:4] ExecIf("Local/90207@zulu-mobile-phone-registered-0000010b;1", "0?Set(Rheader=1)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90207@zulu-mobile-phone-registered-0000010b;1", "1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:6] Set("Local/90207@zulu-mobile-phone-registered-0000010b;1", "sipheader=Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:7] SIPAddHeader("Local/90207@zulu-mobile-phone-registered-0000010b;1", "Alert-Info: Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:8] Set("Local/90207@zulu-mobile-phone-registered-0000010b;1", "PJSIP_HEADER(add,Alert-Info)=Batman;volume=14") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:9] EndWhile("Local/90207@zulu-mobile-phone-registered-0000010b;1", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90207@zulu-mobile-phone-registered-0000010b;1", "0") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("Local/90207@zulu-mobile-phone-registered-0000010b;1", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("Local/90207@zulu-mobile-phone-registered-0000010b;1", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:12] Return("Local/90207@zulu-mobile-phone-registered-0000010b;1", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Spawn extension (zulu-mobile-phone-registered, 207, 1) exited non-zero on 'Local/90207@zulu-mobile-phone-registered-0000010b;1'
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Local/90207@zulu-mobile-phone-registered-0000010b;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Local/90207@zulu-desktop-phone-0000010c;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:1] UserEvent("Local/90207@zulu-desktop-phone-0000010c;1", "zulu-call-b,type:func-apply-sipheaders,to:207,from:") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("Local/90207@zulu-desktop-phone-0000010c;1", "Applying SIP Headers to channel") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:3] Set("Local/90207@zulu-desktop-phone-0000010c;1", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:4] ExecIf("Local/90207@zulu-desktop-phone-0000010c;1", "0?Set(Rheader=1)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90207@zulu-desktop-phone-0000010c;1", "1") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:6] Set("Local/90207@zulu-desktop-phone-0000010c;1", "sipheader=Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:7] SIPAddHeader("Local/90207@zulu-desktop-phone-0000010c;1", "Alert-Info: Batman;volume=14") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:8] Set("Local/90207@zulu-desktop-phone-0000010c;1", "PJSIP_HEADER(add,Alert-Info)=Batman;volume=14") in new stack
[2019-02-28 06:29:38] ERROR[16340][C-000001f8] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:9] EndWhile("Local/90207@zulu-desktop-phone-0000010c;1", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90207@zulu-desktop-phone-0000010c;1", "0") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("Local/90207@zulu-desktop-phone-0000010c;1", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("Local/90207@zulu-desktop-phone-0000010c;1", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@func-apply-sipheaders:12] Return("Local/90207@zulu-desktop-phone-0000010c;1", "") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Spawn extension (zulu-desktop-phone, 207, 1) exited non-zero on 'Local/90207@zulu-desktop-phone-0000010c;1'
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_stack.c: Local/90207@zulu-desktop-phone-0000010c;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_dial.c: Called SIP/207
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_dial.c: Called Local/90207@zulu-mobile-phone-wait
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_dial.c: Called Local/90207@zulu-mobile-phone-registered
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_dial.c: Called Local/90207@zulu-desktop-phone
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_dial.c: Connected line update to SIP/VI_31-000002a5 prevented.
[2019-02-28 06:29:38] VERBOSE[16343][C-000001f8] pbx.c: Executing [90207@zulu-mobile-phone-registered:1] Stasis("Local/90207@zulu-mobile-phone-registered-0000010b;2", "zulu-mobile-call-registered-processing,15,90,") in new stack
[2019-02-28 06:29:38] VERBOSE[16344][C-000001f8] pbx.c: Executing [90207@zulu-desktop-phone:1] Stasis("Local/90207@zulu-desktop-phone-0000010c;2", "zulu-desktop-call-processing,15,90,") in new stack
[2019-02-28 06:29:38] VERBOSE[9972] chan_sip.c: Extension Changed auto_hint_207[from-internal] new state Ringing for Notify User 207
[2019-02-28 06:29:38] VERBOSE[16342][C-000001f8] pbx.c: Executing [90207@zulu-mobile-phone-wait:1] Stasis("Local/90207@zulu-mobile-phone-wait-0000010a;2", "zulu-mobile-call-wait-processing,15,90,") in new stack
[2019-02-28 06:29:38] VERBOSE[16340][C-000001f8] app_dial.c: SIP/207-000002a6 is ringing
[2019-02-28 06:29:38] VERBOSE[9972] chan_sip.c: Extension Changed auto_hint_207[from-internal] new state Ringing for Notify User 207
[2019-02-28 06:29:39] VERBOSE[16343][C-000001f8] pbx.c: Executing [90207@zulu-mobile-phone-registered:2] GotoIf("Local/90207@zulu-mobile-phone-registered-0000010b;2", "0?connected") in new stack
[2019-02-28 06:29:39] VERBOSE[16343][C-000001f8] pbx.c: Executing [90207@zulu-mobile-phone-registered:3] Hangup("Local/90207@zulu-mobile-phone-registered-0000010b;2", "") in new stack
[2019-02-28 06:29:39] VERBOSE[16343][C-000001f8] pbx.c: Spawn extension (zulu-mobile-phone-registered, 90207, 3) exited non-zero on 'Local/90207@zulu-mobile-phone-registered-0000010b;2'
[2019-02-28 06:29:39] VERBOSE[16344][C-000001f8] pbx.c: Executing [90207@zulu-desktop-phone:2] GotoIf("Local/90207@zulu-desktop-phone-0000010c;2", "0?connected") in new stack
[2019-02-28 06:29:39] VERBOSE[16344][C-000001f8] pbx.c: Executing [90207@zulu-desktop-phone:3] Hangup("Local/90207@zulu-desktop-phone-0000010c;2", "") in new stack
[2019-02-28 06:29:39] VERBOSE[16344][C-000001f8] pbx.c: Spawn extension (zulu-desktop-phone, 90207, 3) exited non-zero on 'Local/90207@zulu-desktop-phone-0000010c;2'
[2019-02-28 06:29:39] VERBOSE[16342][C-000001f8] pbx.c: Executing [90207@zulu-mobile-phone-wait:2] GotoIf("Local/90207@zulu-mobile-phone-wait-0000010a;2", "0?connected") in new stack
[2019-02-28 06:29:39] VERBOSE[16342][C-000001f8] pbx.c: Executing [90207@zulu-mobile-phone-wait:3] Hangup("Local/90207@zulu-mobile-phone-wait-0000010a;2", "") in new stack
[2019-02-28 06:29:39] VERBOSE[16342][C-000001f8] pbx.c: Spawn extension (zulu-mobile-phone-wait, 90207, 3) exited non-zero on 'Local/90207@zulu-mobile-phone-wait-0000010a;2'
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] app_macro.c: Spawn extension (macro-dial-one, s, 60) exited non-zero on 'SIP/VI_31-000002a5' in macro 'dial-one'
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on 'SIP/VI_31-000002a5' in macro 'exten-vm'
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Spawn extension (ext-local, 207, 2) exited non-zero on 'SIP/VI_31-000002a5'
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Executing [h@ext-local:1] Macro("SIP/VI_31-000002a5", "hangupcall,") in new stack
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/VI_31-000002a5", "1?theend") in new stack
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-02-28 06:29:41] VERBOSE[9972] chan_sip.c: Extension Changed auto_hint_207[from-internal] new state Idle for Notify User 207
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/VI_31-000002a5", "0?Set(CDR(recordingfile)=)") in new stack
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-hangupcall:4] NoOp("SIP/VI_31-000002a5", "Local/90207@zulu-desktop-phone-0000010c;1 monior file= ") in new stack
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-hangupcall:5] AGI("SIP/VI_31-000002a5", "attendedtransfer-rec-restart.php,Local/90207@zulu-desktop-phone-0000010c;1,") in new stack
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] res_agi.c: <SIP/VI_31-000002a5>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Executing [s@macro-hangupcall:6] Hangup("SIP/VI_31-000002a5", "") in new stack
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'SIP/VI_31-000002a5' in macro 'hangupcall'
[2019-02-28 06:29:41] VERBOSE[16340][C-000001f8] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/VI_31-000002a5'

Full logs of a test call above.

Note, rolled back Core to 14.0.18.41 and the problem still exists. Digium D60 phone.

Rebooted the phone after module rollback, problem still exists. This is a Chan Sip extension.

installed edge version of core 14.0.20 and the problem persists

Use pastebin, it’s much easier to read… pastebin.freepbx.org or pastebin.com

Did some more troubleshooting the Paging Intercom. Updated version by version to 14.0.18.41 to 14.0.18.45 and then 14.0.18.49. Core Version 14.0.18.41 through 14.0.18.45 all work. Breaks when going to 14.0.18.49. I’ve included an internal page-intercom prior to 14.0.18.49 and then after 14.0.18.49 for comparison and troubleshooting.

Full 14.0.18.41 log:
https://pastebin.freepbx.org/view/embed/5aab2909/

Full 14.0.18.49 log:
https://pastebin.freepbx.org/view/embed/969ad21a/

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.

When the upstream formatting changed, going from something like:

Alert-Info: foo

to something like:

Alert-Info: <http://127.0.0.1>;info=foo

the D-Series phones were saddened. At some point in the past (more than 4 years ago), we’d made a change that extracted contents of <> if they were present and that was evaluated. Thus, nothing was getting matched. We’ve got a beta 2_7_4 firmware available for non-D80 models. You can find the 2_7_4 beta at:
http://dphone.dl.digium.com/firmware/beta/2_7_4/
There’s a beta 1_9_7 firmware available for the D80. You can find the 1_9_7 beta at:
http://dphone.dl.digium.com/firmware/beta/1_9_7/

Note that with this update, Alert-Info strings are explicitly matched. So if the server’s sending:

Alert-Info: <http://127.0.0.1>;info=ring=answer

Then the phone’s config line is going to have to look exactly like:

<alert alert_info="&lt;http://127.0.0.1&gt;;info=ring-answer" ringtone_id="Digium" ring_type="ring-answer" />

which if you’re doing old-style DPMA key-value pairs, would be:

alert_info=<http://127.0.0.1>\;info=ring-answer

and where your dialplan is something like:

exten => addheader,1,Set(PJSIP_HEADER(add,Alert-Info)=<http://127.0.0.1>\;info=ring-answer)
1 Like