Sipstation DID Verification anomaly

tonysims · December 17, 2020, 9:11am

When I create a inbound route and point it to Sipstation DID verification I get a recorded announcement detailing my calling and called numbers which is just what I want however when I direct the inbound route to an announcement with it’s destination after playback directed to Sipstation DID it does not work.

Any thoughts? I am wondering if the calling / called information is somehow lost during the transfer to the announcement module.

lgaetz · December 17, 2020, 1:02pm

That’s an unusual configuration, but something I would still expect to work. Can you share a call trace via pastebin of one of these calls?
https://wiki.freepbx.org/display/SUP/Providing+Great+Debug#ProvidingGreatDebug-AsteriskLogs-PartII

tonysims · December 17, 2020, 3:05pm

Hi, thank you for responding, here’s the trace you requested. It plays the recording file “custom/UnassociatedConnection-Kiela.alaw” without issue and then dies before executing SipStation so a search for "Playing ‘custom/UnassociatedConnection-Kiela.alaw’ looks like an easy way to find where something’s going wrong.

[2020-12-17 14:58:05] VERBOSE[25783] pbx_variables.c: Setting global variable ‘S [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx_builtins.c: Goto (sub-record [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@sub-record-c [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx_builtins.c: Goto (sub-record [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [in@sub-record- [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [in@sub-record- [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [in@sub-record- [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [in@sub-record- [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [recordcheck@su [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [recordcheck@su [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx_builtins.c: Goto (sub-record [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [recordcheck@su [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [in@sub-record- [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-blacklis [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-blacklis [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-blacklis [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx_builtins.c: Goto (from-pstn, [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] res_agi.c: <PJSIP/CUCM_TRUNK_10. [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [202010010002@f [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx_builtins.c: Goto (app-announ [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-announce [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-announce [2020-12-17 14:58:05] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-announce [2020-12-17 14:58:06] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-announce [2020-12-17 14:58:06] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-announce [2020-12-17 14:58:06] VERBOSE[1762][C-00000008] file.c: <PJSIP/CUCM_TRUNK_10.0.5 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@app-announce [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx_builtins.c: Goto (sipstation [2020-12-17 14:58:11] WARNING[1762][C-00000008] pbx.c: Channel ‘PJSIP/CUCM_TRUNK [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] app_stack.c: PJSIP/CUCM_TRUNK_10 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:1 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:2 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:3 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:4 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:5 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:6 [2020-12-17 14:58:11] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:7 [2020-12-17 14:58:12] VERBOSE[1762][C-00000008] res_agi.c: <PJSIP/CUCM_TRUNK_10. [2020-12-17 14:58:12] VERBOSE[1762][C-00000008] pbx.c: Executing [s@crm-hangup:8 [2020-12-17 14:58:12] VERBOSE[1762][C-00000008] app_stack.c: Spawn extension (si IPDOMAIN’ to ‘10.0.55.25’
rom-pstn:1] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__DIRECTION=INBOUND”) i n new stack
rom-pstn:2] Gosub(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “sub-record-check,s,1( in,202010010002,dontcare)”) in new stack
heck:1] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?initialized”) in new s tack
heck:2] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__REC_STATUS=INITIALIZED”) in new stack
heck:3] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “NOW=1608217085”) in new sta ck
heck:4] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__DAY=17”) in new stack
heck:5] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__MONTH=12”) in new stack
heck:6] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__YEAR=2020”) in new stack
heck:7] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__TIMESTR=20201217-145805”) in new stack
heck:8] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__FROMEXTEN=unknown”) in ne w stack
heck:9] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__MON_FMT=wav”) in new stac k
heck:10] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “Recordings initialized”) in new stack
heck:11] ExecIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?Set(ARG3=dontcare)”) in new stack
heck:12] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “REC_POLICY_MODE_SAVE=”) in new stack
heck:13] ExecIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?Set(REC_STATUS=NO)”) in new stack
heck:14] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “2?checkaction”) in new stack
-check,s,17)
heck:17] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, "1?sub-record-check,in,1 ") in new stack
-check,in,1)
check:1] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “Inbound Recording Check t o 202010010002”) in new stack
check:2] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “FROMEXTEN=unknown”) in new stack
check:3] ExecIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “12?Set(FROMEXTEN=102010 010001)”) in new stack
check:4] Gosub(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “recordcheck,1(dontcare,i n,202010010002)”) in new stack
b-record-check:1] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “Starting recordi ng check against dontcare”) in new stack
b-record-check:2] Goto(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “dontcare”) in ne w stack
-check,recordcheck,3)
b-record-check:3] Return(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “”) in new stac k
check:5] Return(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “”) in new stack
rom-pstn:3] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “CHANNEL(tonezone)=us”) in new stack
rom-pstn:4] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, "__FROM_DID=202010010002 ") in new stack
rom-pstn:5] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “returnhere=1”) in new s tack
rom-pstn:6] Gosub(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “app-blacklist-check,s ,1()”) in new stack
t-check:1] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?blacklisted”) in ne w stack
t-check:2] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “CALLED_BLACKLIST=1”) in new stack
t-check:3] Return(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “”) in new stack
rom-pstn:7] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “CDR(did)=202010010002”) in new stack
rom-pstn:8] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?”) in new stack
rom-pstn:9] ExecIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “1 ?Set(CALLERID(name )=102010010001)”) in new stack
rom-pstn:10] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__MOHCLASS=”) in new s tack
rom-pstn:11] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__REVERSAL_REJECT=FALS E”) in new stack
rom-pstn:12] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “1?post-reverse-char ge”) in new stack
202010010002,14)
rom-pstn:14] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “”) in new stack
rom-pstn:15] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__CALLINGNAMEPRES_SV=a llowed_not_screened”) in new stack
rom-pstn:16] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__CALLINGNUMPRES_SV=al lowed_not_screened”) in new stack
rom-pstn:17] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “CALLERID(name-pres)=al lowed_not_screened”) in new stack
rom-pstn:18] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “CALLERID(num-pres)=all owed_not_screened”) in new stack
rom-pstn:19] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “CallerID Entry Point” ) in new stack
rom-pstn:20] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__CRM_DIRECTION=INBOUN D”) in new stack
rom-pstn:21] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__CRM_SOURCE=102010010 001”) in new stack
rom-pstn:22] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__CRM_LINKEDID=1608217 085.11”) in new stack
rom-pstn:23] AGI(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “agi://127.0.0.1/sangom acrm.agi,true”) in new stack
0.56.30-00000007>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
rom-pstn:24] ExecIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “1?Set(CHANNEL(hangu p_handler_push)=crm-hangup,s,1)”) in new stack
rom-pstn:25] Goto(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “app-announcement-5,s, 1”) in new stack
cement-5,s,1)
ment-5:1] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?begin”) in new stack
ment-5:2] Answer(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “”) in new stack
ment-5:3] Wait(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “1”) in new stack
ment-5:4] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “Playing announcement Una ssociated Connection”) in new stack
ment-5:5] Playback(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “custom/UnassociatedC onnection-Kiela,noanswer”) in new stack
6.30-00000007> Playing ‘custom/UnassociatedConnection-Kiela.alaw’ (language ‘en’ )
ment-5:6] Goto(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “sipstation-welcome,s,1”) in new stack
-welcome,s,1)
_10.0.56.30-00000007’ sent to invalid extension but no invalid handler: context, exten,priority=sipstation-welcome,s,1
.0.56.30-00000007 Internal Gosub(crm-hangup,s,1) start
] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “Sending Hangup to CRM”) in new s tack
] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “HANGUP CAUSE: 0”) in new stack
] ExecIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?Set(__CRM_VOICEMAIL=)”) in n ew stack
] NoOp(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “MASTER CHANNEL: 1608217085.11 = 1608217085.11”) in new stack
] GotoIf(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “0?return”) in new stack
] Set(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “__CRM_HANGUP=1”) in new stack
] AGI(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “agi://127.0.0.1/sangomacrm.agi”) in new stack
0.56.30-00000007>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
] Return(“PJSIP/CUCM_TRUNK_10.0.56.30-00000007”, “”) in new stack
pstation-welcome, s, 1) exited non-zero on 'PJSIP/CUCM_TRUNK_10.0.56.30-00000007

lgaetz · December 17, 2020, 3:12pm

Pastebin pls, instructions are as per link provided.

tonysims · December 17, 2020, 3:16pm

Done with title SIPSTATION

lgaetz · December 17, 2020, 3:20pm

The formatting is garbage, and I can’t tell if spaces are because of a FreePBX bug, or if it’s because of the way you are sharing. The instructions for piping directly to pastebin are in the link above, please do it that way instead of cut/paste.

Actually, never mind, I think I see the issue … standby

lgaetz · December 17, 2020, 3:37pm

I found the issue and opened an internal ticket. At present, the only place the DID verification destination can be used is on an inbound route. If you want to work around this, instead of using the built in destination, you can create a Custom Destination with a goto string of:

sipstation-welcome,${FROM_DID},1

tonysims · December 17, 2020, 3:52pm

Interesting, have tried your suggestion and can now see SIPSTATION call containing the called number as opposed to an “s” but it still doesn’t read announce back my calling and called number as it should.

[2020-12-17 15:46:58] VERBOSE[8522][C-0000000a] file.c: <PJSIP/CUCM_TRUNK_10.0.56.30-00000009> Playing ‘custom/UnassociatedConnection-Kiela.alaw’ (language ‘en’)
[2020-12-17 15:47:03] VERBOSE[8522][C-0000000a] pbx.c: Executing [s@app-announcement-5:6] Goto(“PJSIP/CUCM_TRUNK_10.0.56.30-00000009”, “sipstation_welcome,202010010002,1”) in new stack
[2020-12-17 15:47:03] VERBOSE[8522][C-0000000a] pbx_builtins.c: Goto (sipstation_welcome,202010010002,1)
[2020-12-17 15:47:03] WARNING[8522][C-0000000a] pbx.c: Channel ‘PJSIP/CUCM_TRUNK_10.0.56.30-00000009’ sent to invalid extension but no invalid handler: context,exten,priority=sipstation_welcome,202010010002,1
[2020-12-17 15:47:03] VERBOSE[8522][C-0000000a] app_stack.c: PJSIP/CUCM_TRUNK_10.0.56.30-00000009 Internal Gosub(crm-hangup,s,1) start

lgaetz · December 17, 2020, 3:55pm

Typo on my part (now fixed), the context has a hyphen not an underscore:

sipstation-welcome

tonysims · December 17, 2020, 4:02pm

perfect, that works now - you’re a star

lgaetz · January 28, 2021, 12:30pm

This is resolved in FreePBX 15.

system · June 3, 2021, 11:05pm

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