Problem with outbound call to alarm number

jaymef · October 26, 2018, 11:10pm

Config:

FreePBX 14.0.3.25 (everything updated to latest versions)
Provider: Vitelity

I rebuilt an old trixbox system on FreePBX, it’s a basic setup with light use. All regular personal extensions are working as intended inbound/outbound.

We had an alarm system using an extension (I know this is generally not recommended, but it had been working for years). The phone system plugs in to a cisco spa112 phone adapter (no settings on it have been changed).

We’ve noticed that the alarm system is reporting a problem connecting to the number. The SIP status is good, connected/registered. I can plug a landline in to it and dial out without a problem.

I look at the asterisk logs and can see the extension trying to dial the alarm company number which is a toll free 1844xxx-xxx number. It’s just not answering. If I call this number from my cell phone I get an answer similar to a fax machine. If I try calling it directly from a sip phone/software I just hear silence for 10-20 seconds or so and a message “number is not answering”

I’m not really sure why the number does not pick up when called from asterisk. I’m thinking potentially some sort of problem with codecs but I don’t get any indication of that from the logs. Here is an example log of me trying to dial this number from a sip extension:

Any help or further troubleshooting tips would be greatly appreciated. Thanks!

[2018-10-26 20:06:38] VERBOSE[21551][C-00000092] netsock2.c: Using SIP RTP TOS bits 184
[2018-10-26 20:06:38] VERBOSE[21551][C-00000092] netsock2.c: Using SIP RTP CoS mark 5
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [1844XXXXXXX@from-internal:1] Macro(“SIP/199-0000005f”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:1] Set(“SIP/199-0000005f”, “TOUCH_MONITOR=1540595198.95”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/199-0000005f”, “AMPUSER=199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“SIP/199-0000005f”, “0?report”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/199-0000005f”, “1?Set(REALCALLERIDNUM=199)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:5] Set(“SIP/199-0000005f”, “AMPUSER=199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“SIP/199-0000005f”, “0?limit”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:7] Set(“SIP/199-0000005f”, “AMPUSERCIDNAME=test”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“SIP/199-0000005f”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“SIP/199-0000005f”, “0?report”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:10] Set(“SIP/199-0000005f”, “AMPUSERCID=199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:11] Set(“SIP/199-0000005f”, “__DIAL_OPTIONS=HhTtr”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:12] Set(“SIP/199-0000005f”, “CALLERID(all)=“test” <199>”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:13] GotoIf(“SIP/199-0000005f”, “0?limit”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:14] ExecIf(“SIP/199-0000005f”, “1?Set(GROUP(concurrency_limit)=199)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:15] ExecIf(“SIP/199-0000005f”, “0?Set(CHANNEL(language)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“SIP/199-0000005f”, “Macro Depth is 1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“SIP/199-0000005f”, “1?report2:macroerror”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:18] GotoIf(“SIP/199-0000005f”, “1?continue”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:37] Set(“SIP/199-0000005f”, “CALLERID(number)=199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:38] Set(“SIP/199-0000005f”, “CALLERID(name)=test”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“SIP/199-0000005f”, “0?cnum”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:40] Set(“SIP/199-0000005f”, “CDR(cnam)=test”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:41] Set(“SIP/199-0000005f”, “CDR(cnum)=199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-user-callerid:42] Set(“SIP/199-0000005f”, “CHANNEL(language)=en”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [1844XXXXXXX@from-internal:2] Gosub(“SIP/199-0000005f”, “sub-record-check,s,1(out,1844XXXXXXX,dontcare)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/199-0000005f”, “0?initialized”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/199-0000005f”, “__REC_STATUS=INITIALIZED”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/199-0000005f”, “NOW=1540595198”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/199-0000005f”, “__DAY=26”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/199-0000005f”, “__MONTH=10”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/199-0000005f”, “__YEAR=2018”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/199-0000005f”, “__TIMESTR=20181026-200638”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/199-0000005f”, “__FROMEXTEN=199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/199-0000005f”, “__MON_FMT=wav”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/199-0000005f”, “Recordings initialized”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/199-0000005f”, “0?Set(ARG3=dontcare)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/199-0000005f”, “REC_POLICY_MODE_SAVE=”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/199-0000005f”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/199-0000005f”, “3?checkaction”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/199-0000005f”, “1?sub-record-check,out,1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (sub-record-check,out,1)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [out@sub-record-check:1] NoOp(“SIP/199-0000005f”, “Outbound Recording Check from 199 to 1844XXXXXXX”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [out@sub-record-check:2] Set(“SIP/199-0000005f”, “RECMODE=dontcare”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [out@sub-record-check:3] ExecIf(“SIP/199-0000005f”, “1?Goto(routewins)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (sub-record-check,out,7)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [out@sub-record-check:7] Gosub(“SIP/199-0000005f”, “recordcheck,1(dontcare,out,1844XXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/199-0000005f”, “Starting recording check against dontcare”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/199-0000005f”, “dontcare”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [out@sub-record-check:8] Return(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [1844XXXXXXX@from-internal:3] ExecIf(“SIP/199-0000005f”, “0 ?Set(CDR(accountcode)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [1844XXXXXXX@from-internal:4] Set(“SIP/199-0000005f”, “MOHCLASS=default”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [1844XXXXXXX@from-internal:5] Set(“SIP/199-0000005f”, “_NODEST=”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [1844XXXXXXX@from-internal:6] Macro(“SIP/199-0000005f”, “dialout-trunk,1,1844XXXXXXX,off”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:1] Set(“SIP/199-0000005f”, “DIAL_TRUNK=1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf(“SIP/199-0000005f”, “0?Set(DIAL_OPTIONS=Hhtr)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf(“SIP/199-0000005f”, “0?sub-pincheck,s,1()”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERID(num)=199)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf(“SIP/199-0000005f”, “0?disabletrunk,1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:6] Set(“SIP/199-0000005f”, “DIAL_NUMBER=1844XXXXXXX”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:7] Set(“SIP/199-0000005f”, “DIAL_TRUNK_OPTIONS=HhTtr”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:8] Set(“SIP/199-0000005f”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:9] Set(“SIP/199-0000005f”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf(“SIP/199-0000005f”, “0?nomax”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf(“SIP/199-0000005f”, “0?chanfull”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf(“SIP/199-0000005f”, “0?skipoutcid”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:13] Macro(“SIP/199-0000005f”, “outbound-callerid,1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp(“SIP/199-0000005f”, “199”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp(“SIP/199-0000005f”, “off”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERPRES(name-pres)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERPRES(num-pres)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf(“SIP/199-0000005f”, “0?Set(REALCALLERIDNUM=199)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:7] ExecIf(“SIP/199-0000005f”, “0?Set(AMPUSER=199)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:8] GotoIf(“SIP/199-0000005f”, “1?normcid”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:12] Set(“SIP/199-0000005f”, "USEROUTCID=“test” ") in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:13] Set(“SIP/199-0000005f”, “EMERGENCYCID=”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:14] Set(“SIP/199-0000005f”, “TRUNKOUTCID=”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:15] GotoIf(“SIP/199-0000005f”, “1?trunkcid”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:20] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERID(all)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf(“SIP/199-0000005f”, “1?Set(CALLERID(all)=“test” )”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERID(all)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERPRES(name-pres)=prohib_passed_screen)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf(“SIP/199-0000005f”, “0?Set(CALLERPRES(num-pres)=prohib_passed_screen)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:25] Set(“SIP/199-0000005f”, “CDR(outbound_cnum)=XXXXXXXXXX”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-outbound-callerid:26] Set(“SIP/199-0000005f”, “CDR(outbound_cnam)=test”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf(“SIP/199-0000005f”, “1?sub-flp-1,s,1()”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-flp-1:1] ExecIf(“SIP/199-0000005f”, “0?Return()”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@sub-flp-1:2] Return(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:15] Set(“SIP/199-0000005f”, “OUTNUM=1844XXXXXXX”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:16] Set(“SIP/199-0000005f”, “custom=SIP/vitel-outbound”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf(“SIP/199-0000005f”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf(“SIP/199-0000005f”, “0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:19] Macro(“SIP/199-0000005f”, “dialout-trunk-predial-hook,”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf(“SIP/199-0000005f”, “0?bypass,1”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf(“SIP/199-0000005f”, “1?Set(CONNECTEDLINE(num,i)=1844XXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf(“SIP/199-0000005f”, “1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf(“SIP/199-0000005f”, “1?Set(CONNECTEDLINE(num,i)=1844XXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf(“SIP/199-0000005f”, “1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf(“SIP/199-0000005f”, “0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)XXXXXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf(“SIP/199-0000005f”, “0?customtrunk”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:25] Dial(“SIP/199-0000005f”, “SIP/vitel-outbound/1844XXXXXXX,300,Tb(func-apply-sipheaders^s^1)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] netsock2.c: Using SIP RTP TOS bits 184
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] netsock2.c: Using SIP RTP CoS mark 5
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_stack.c: SIP/vitel-outbound-00000060 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp(“SIP/vitel-outbound-00000060”, “Applying SIP Headers to channel”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:2] Set(“SIP/vitel-outbound-00000060”, “SIPHEADERKEYS=”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:3] ExecIf(“SIP/vitel-outbound-00000060”, “0?Set(Rheader=1)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:4] While(“SIP/vitel-outbound-00000060”, “0”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_while.c: Jumping to priority 8
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf(“SIP/vitel-outbound-00000060”, “0?SIPRemoveHeader(Alert-Info:)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf(“SIP/vitel-outbound-00000060”, “0?Set(PJSIP_HEADER(remove,Alert-Info)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:11] Return(“SIP/vitel-outbound-00000060”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_stack.c: Spawn extension (from-trunk, 1844XXXXXXX, 1) exited non-zero on ‘SIP/vitel-outbound-00000060’
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_stack.c: SIP/vitel-outbound-00000060 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_dial.c: Called SIP/vitel-outbound/1844XXXXXXX
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp(“SIP/199-0000005f”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 18”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf(“SIP/199-0000005f”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set(“SIP/199-0000005f”, “RC=18”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto(“SIP/199-0000005f”, “18,1”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-dialout-trunk,18,1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [18@macro-dialout-trunk:1] Goto(“SIP/199-0000005f”, “s-NOANSWER,1”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-dialout-trunk,s-NOANSWER,1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-NOANSWER@macro-dialout-trunk:1] NoOp(“SIP/199-0000005f”, “Dial failed due to trunk reporting NOANSWER - giving up”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-NOANSWER@macro-dialout-trunk:2] Progress(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-NOANSWER@macro-dialout-trunk:3] Playback(“SIP/199-0000005f”, “number-not-answering,noanswer”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] file.c: <SIP/199-0000005f> Playing ‘number-not-answering.ulaw’ (language ‘en’)
:1
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf(“SIP/199-0000005f”, “0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)XXXXXXXXXX)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf(“SIP/199-0000005f”, “0?customtrunk”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:25] Dial(“SIP/199-0000005f”, “SIP/vitel-outbound/1844XXXXXXX,300,Tb(func-apply-sipheaders^s^1)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] netsock2.c: Using SIP RTP TOS bits 184
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] netsock2.c: Using SIP RTP CoS mark 5
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_stack.c: SIP/vitel-outbound-00000060 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp(“SIP/vitel-outbound-00000060”, “Applying SIP Headers to channel”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:2] Set(“SIP/vitel-outbound-00000060”, “SIPHEADERKEYS=”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:3] ExecIf(“SIP/vitel-outbound-00000060”, “0?Set(Rheader=1)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:4] While(“SIP/vitel-outbound-00000060”, “0”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_while.c: Jumping to priority 8
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf(“SIP/vitel-outbound-00000060”, “0?SIPRemoveHeader(Alert-Info:)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf(“SIP/vitel-outbound-00000060”, “0?Set(PJSIP_HEADER(remove,Alert-Info)=)”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] pbx.c: Executing [s@func-apply-sipheaders:11] Return(“SIP/vitel-outbound-00000060”, “”) in new stack
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_stack.c: Spawn extension (from-trunk, 1844XXXXXXX, 1) exited non-zero on ‘SIP/vitel-outbound-00000060’
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_stack.c: SIP/vitel-outbound-00000060 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-10-26 20:06:38] VERBOSE[26467][C-00000092] app_dial.c: Called SIP/vitel-outbound/1844XXXXXXX
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp(“SIP/199-0000005f”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 18”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf(“SIP/199-0000005f”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set(“SIP/199-0000005f”, “RC=18”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto(“SIP/199-0000005f”, “18,1”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-dialout-trunk,18,1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [18@macro-dialout-trunk:1] Goto(“SIP/199-0000005f”, “s-NOANSWER,1”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx_builtins.c: Goto (macro-dialout-trunk,s-NOANSWER,1)
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-NOANSWER@macro-dialout-trunk:1] NoOp(“SIP/199-0000005f”, “Dial failed due to trunk reporting NOANSWER - giving up”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-NOANSWER@macro-dialout-trunk:2] Progress(“SIP/199-0000005f”, “”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] pbx.c: Executing [s-NOANSWER@macro-dialout-trunk:3] Playback(“SIP/199-0000005f”, “number-not-answering,noanswer”) in new stack
[2018-10-26 20:07:09] VERBOSE[26467][C-00000092] file.c: <SIP/199-0000005f> Playing ‘number-not-answering.ulaw’ (language ‘en’)

BlazeStudios · October 26, 2018, 11:44pm

18 is translated from a 408 error which is a timeout. So either Vitelity is timing on your request or one of the “hops” between Vitelity and the other side are timing out.

You need to do a call again with the SIP debug running so we can see the progress of the SIP messages/call between you and Vitelity.

asterisk -r
sip set debug on

make call and post the output.

jaymef · October 27, 2018, 11:19am

Thanks for your reply, sorry I’ve been trying to post a debug log for a bit but have length issues now it’s complaining about not being able to post links as a new users, I tried redacting as much as I could but no luck yet hah.

Stewart1 · October 27, 2018, 4:14pm

Set SIP debug and make test call as instructed by @BlazeStudios .
Get log file, redact as desired, paste at https://pastebin.freepbx.org/ .
Check the Create Shorturl box and create the paste. The link will look like
https://pastebin.freepbx.org/view/1234abcd
Post the eight hex digits after /view/ here.

jaymef · October 27, 2018, 5:29pm

Thanks for the tip, here is the paste: 42cb5f43

Stewart1 · October 27, 2018, 6:23pm

Just guessing here, the 902367XXXX caller ID you are sending may be in the wrong format; Vitelity may require 1902367XXXX. Does the correct caller ID appear when you call your own mobile via the same trunk?

Next, although Vitelity is IMO a first-class operation, it’s possible that they are messing up in this case. They are a US company and might be passing a US ANI, which your alarm company (which I assume is in Nova Scotia) may be rejecting.

What do you hear when calling 1 800 437 7950?

For further testing, I can try calling the alarm receiver number with my Vitelity trunk and others. Can you please PM it to me (there is no reason to keep it secret, as it is shared by thousands of other customers of the monitoring service)?

jaymef · October 27, 2018, 6:41pm

Thanks for taking a look, I suppose anything is possible. Important to note that this isn’t a log of the alarm system calling, but me testing the number it’s dialling from another sip extension on the system. When I call 1 800 437 7950 it picks up and tells me that I am calling from my sip number.

The alarm number I’m trying to dial: 18443104017

I should mention again that all other numbers being dialed seem to be fine, including several other toll free numbers I’ve tested and even some random 1844 numbers.

This one differs of course because it’s an alarm system number and answers differently.

I don’t have a lot of detailed knowledge about the old setup that was on trixbox before (and apparently working fine) but I do recall that we had a second provider I believe voicenetworks for long distance calls and we moved everything to Vietality and closed voicenetworks when we rebuilt on new freePBX setup. I’m wondering if perhaps the number was routing through voicenetworks in the past and now that it’s going through vietality that is causing a problem somewhere. Of course this may not be related, we did upgrade quite an old setup in to a completely new build so pretty much anything could be different.

lgaetz · October 27, 2018, 7:01pm

Shout out to a fellow bluenoser!

Stewart1 · October 27, 2018, 7:35pm

OK, so I can call the receiver successfully with Vitelity when the caller ID is US, but when it’s Canadian the call times out as you observed. (I tried several NS and QC numbers).

While you could work around the problem by sending a spoofed caller ID, the alarm company would likely notice the discrepancy and contact you to resolve it (though they would probably still dispatch for a genuine alarm with incorrect caller ID). Possibly, spoofing your mobile number will work.

Otherwise, I suggest that you open a ticket with Vitelity – they typically respond very well.

If that doesn’t work out, there are several free alternative paths for toll free calls.

Stewart1 · October 27, 2018, 7:45pm

FWIW, I tested successfully with Flowroute, using your 902 number as caller ID.
If you sign up with them, they give you a $0.25 test credit. If you are careful not to spend it down (don’t send them any non-toll-free calls), the credit should last forever. Long term, they may be a suitable backup for you.

jaymef · October 28, 2018, 11:12am

Wow, this was some great detective work. I don’t think I would have ever guessed that it was CID related. On my test SIP extension I set a fake US caller ID and confirmed that the number does pick up. I assume it would satisfy the alarm check as well, I’ll have to test that monday.

Like you said, it’s probably not a good idea to spoof the number so I’ll see if Vitelity can offer any other solution.

Thanks again for your help with this, really appreciate it!

PitzKey · October 28, 2018, 2:06pm

Solid work @Stewart1 well done!

tonyclewis · October 28, 2018, 3:31pm

This is becoming a bigger issue for lots of providers that it appears alot of Canada Toll Free providers block calls from a Canada CID if they know you are routing from a US based carrier. We have customers in SIPStation that have had this problem and had to work through it with a carrier who would mascrade we are US based tonroute those calls of course at a higher premium cost to us.

system · November 4, 2018, 3:34pm

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