Sipstation DID Verification anomaly


(Tony Sims) #1

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.


(Lorne Gaetz) #2

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


(Tony Sims) #3

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


(Lorne Gaetz) #4

Pastebin pls, instructions are as per link provided.


(Tony Sims) #5

Done with title SIPSTATION


(Lorne Gaetz) #6

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


(Lorne Gaetz) #7

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

(Tony Sims) #8

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


(Lorne Gaetz) #9

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

sipstation-welcome

(Tony Sims) #10

perfect, that works now - you’re a star


(Lorne Gaetz) #11

This is resolved in FreePBX 15.