Outbound CID not passing but shows in CDR report

rwize · 2020-01-11 02:37:35 UTC

I have just deployed a new Distro FreepBX and patched it fully Current PBX Version: 15.0.16.38

Current System Version:12.7.6-1910-1.sng7 Astersik 16.

I have a number of other PBX’s that are not having the the following issue and the same SIP provider is being used. I understand that Outbound CID is configured in 4 or 5 places and in this case I have configured the CID to present at the Outbound Route level. In the end it doesn’t matter if a configure a CID on the Trunk and enable Force Trunk CID, the end result is the carrier only is presented with the trunk name and thus people receiving the call see ‘unknown’ caller.

In the example below, I have created a Device 9991001 associated to extension 999 and I have called the outside number of 647-502-1488.

Here are the PBX logs as well as the NetCapture logs. Really appreciate any input on this one… I am pulling my hair out.

-----------PBX Logs-----------------

[2020-01-10 15:53:53] VERBOSE[8830][C-000000dc] pbx.c: Executing [s@macro-user-callerid:38] Set(“SIP/9991001-00000102”, “CALLERID(number)=999”) in new stack
[2020-01-10 15:55:43] NOTICE[2649] chan_sip.c: Received SIP subscribe for peer without mailbox: 9991001
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@from-internal:1] Macro(“SIP/9991001-00000103”, “user-callerid,LIMIT”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:1] Set(“SIP/9991001-00000103”, “TOUCH_MONITOR=1578689784.310”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/9991001-00000103”, “AMPUSER=9991001”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“SIP/9991001-00000103”, “0?report”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/9991001-00000103”, “1?Set(REALCALLERIDNUM=9991001)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:5] Set(“SIP/9991001-00000103”, “AMPUSER=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“SIP/9991001-00000103”, “0?limit”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:7] Set(“SIP/9991001-00000103”, “AMPUSERCIDNAME=IHF Testing”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“SIP/9991001-00000103”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“SIP/9991001-00000103”, “0?report”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:10] Set(“SIP/9991001-00000103”, “AMPUSERCID=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:11] Set(“SIP/9991001-00000103”, “__DIAL_OPTIONS=HhTtr”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:12] Set(“SIP/9991001-00000103”, “CALLERID(all)=“IHF Testing” <999>”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:13] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERID(all)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:14] GotoIf(“SIP/9991001-00000103”, “0?limit”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:15] ExecIf(“SIP/9991001-00000103”, “1?Set(GROUP(concurrency_limit)=999)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:16] ExecIf(“SIP/9991001-00000103”, “0?Set(CHANNEL(language)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:17] NoOp(“SIP/9991001-00000103”, “Macro Depth is 1”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:18] GotoIf(“SIP/9991001-00000103”, “1?report2:macroerror”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:19] GotoIf(“SIP/9991001-00000103”, “1?continue”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:38] Set(“SIP/9991001-00000103”, “CALLERID(number)=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:39] Set(“SIP/9991001-00000103”, “CALLERID(name)=IHF Testing”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:40] GotoIf(“SIP/9991001-00000103”, “0?cnum”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:41] Set(“SIP/9991001-00000103”, “CDR(cnam)=IHF Testing”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:42] Set(“SIP/9991001-00000103”, “CDR(cnum)=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-user-callerid:43] Set(“SIP/9991001-00000103”, “CHANNEL(language)=en”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@from-internal:2] Set(“SIP/9991001-00000103”, “ROUTEUSER=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@from-internal:3] Set(“SIP/9991001-00000103”, “ROUTEUSER=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@from-internal:4] GotoIf(“SIP/9991001-00000103”, “1?notblind”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@from-internal:7] GotoIf(“SIP/9991001-00000103”, “1?restrictedroute-c81e728d9d4c2f636f067f89cc14862c,6475021488,2:outbound-allroutes,6475021488,2”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:2] Gosub(“SIP/9991001-00000103”, “sub-record-check,s,1(out,6475021488,dontcare)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/9991001-00000103”, “0?initialized”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/9991001-00000103”, “__REC_STATUS=INITIALIZED”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/9991001-00000103”, “NOW=1578689784”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/9991001-00000103”, “__DAY=10”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/9991001-00000103”, “__MONTH=01”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/9991001-00000103”, “__YEAR=2020”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/9991001-00000103”, “__TIMESTR=20200110-155624”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/9991001-00000103”, “__FROMEXTEN=999”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/9991001-00000103”, “__MON_FMT=WAV”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/9991001-00000103”, “Recordings initialized”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/9991001-00000103”, “0?Set(ARG3=dontcare)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/9991001-00000103”, “REC_POLICY_MODE_SAVE=”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/9991001-00000103”, “0?Set(REC_STATUS=NO)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/9991001-00000103”, “3?checkaction”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/9991001-00000103”, “1?sub-record-check,out,1”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [out@sub-record-check:1] NoOp(“SIP/9991001-00000103”, “Outbound Recording Check from 999 to 6475021488”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [out@sub-record-check:2] Set(“SIP/9991001-00000103”, “RECMODE=dontcare”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [out@sub-record-check:3] ExecIf(“SIP/9991001-00000103”, “1?Goto(routewins)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [out@sub-record-check:7] Gosub(“SIP/9991001-00000103”, “recordcheck,1(dontcare,out,6475021488)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/9991001-00000103”, “Starting recording check against dontcare”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/9991001-00000103”, “dontcare”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“SIP/9991001-00000103”, “”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [out@sub-record-check:8] Return(“SIP/9991001-00000103”, “”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:3] ExecIf(“SIP/9991001-00000103”, “0 ?Set(CDR(accountcode)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:4] Set(“SIP/9991001-00000103”, “MOHCLASS=default”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:5] Set(“SIP/9991001-00000103”, “_NODEST=”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [6475021488@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:6] Macro(“SIP/9991001-00000103”, “dialout-trunk,2,6475021488,off”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:1] Set(“SIP/9991001-00000103”, “DIAL_TRUNK=2”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf(“SIP/9991001-00000103”, “0?Set(DIAL_OPTIONS=Hhtr)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf(“SIP/9991001-00000103”, “0?sub-pincheck,s,1()”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERID(num)=999)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf(“SIP/9991001-00000103”, “0?disabletrunk,1”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:6] Set(“SIP/9991001-00000103”, “DIAL_NUMBER=6475021488”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:7] Set(“SIP/9991001-00000103”, “DIAL_TRUNK_OPTIONS=HhTtr”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:8] Set(“SIP/9991001-00000103”, “OUTBOUND_GROUP=OUT_2”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:9] Set(“SIP/9991001-00000103”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf(“SIP/9991001-00000103”, “0?nomax”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf(“SIP/9991001-00000103”, “0?chanfull”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf(“SIP/9991001-00000103”, “0?skipoutcid”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:13] Macro(“SIP/9991001-00000103”, “outbound-callerid,2”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp(“SIP/9991001-00000103”, “9991001”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp(“SIP/9991001-00000103”, “”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp(“SIP/9991001-00000103”, “off”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERPRES(name-pres)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERPRES(num-pres)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf(“SIP/9991001-00000103”, “0?Set(REALCALLERIDNUM=999)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:7] ExecIf(“SIP/9991001-00000103”, “0?Set(AMPUSER=999)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:8] GotoIf(“SIP/9991001-00000103”, “1?normcid”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:12] Set(“SIP/9991001-00000103”, “USEROUTCID=”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:13] Set(“SIP/9991001-00000103”, “EMERGENCYCID=”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:14] Set(“SIP/9991001-00000103”, “TRUNKOUTCID=xxxxx-client did-xxx”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:15] GotoIf(“SIP/9991001-00000103”, “1?trunkcid”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf(“SIP/9991001-00000103”, “1?Set(CALLERID(all)=xxxxx-client did-xxx)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERID(all)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERID(all)=)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERID(all)=9991001)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:25] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERPRES(name-pres)=prohib_passed_screen)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:26] ExecIf(“SIP/9991001-00000103”, “0?Set(CALLERPRES(num-pres)=prohib_passed_screen)”) in new stack
[2020-01-10 15:56:24] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:27] Set(“SIP/9991001-00000103”, “CDR(outbound_cnum)=xxxxx-client did-xxx”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-outbound-callerid:28] Set(“SIP/9991001-00000103”, “CDR(outbound_cnam)=”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf(“SIP/9991001-00000103”, “0?sub-flp-2,s,1()”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:15] Set(“SIP/9991001-00000103”, “OUTNUM=6475021488”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:16] Set(“SIP/9991001-00000103”, “custom=SIP/LUCID-EYET-Main”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf(“SIP/9991001-00000103”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf(“SIP/9991001-00000103”, “0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:19] Macro(“SIP/9991001-00000103”, “dialout-trunk-predial-hook,”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/9991001-00000103”, “”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf(“SIP/9991001-00000103”, “0?skipcrm”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:21] Set(“SIP/9991001-00000103”, “__CRM_DIRECTION=OUTBOUND”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:22] Set(“SIP/9991001-00000103”, “__CRM_DESTINATION=xxxxx-client did-xxx”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:23] Set(“SIP/9991001-00000103”, “__CRM_SOURCE=999”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:24] AGI(“SIP/9991001-00000103”, “agi://127.0.0.1/sangomacrm.agi”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] res_agi.c: <SIP/9991001-00000103>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:25] Set(“SIP/9991001-00000103”, “CHANNEL(hangup_handler_push)=crm-hangup,s,1”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp(“SIP/9991001-00000103”, “CRM Finished”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf(“SIP/9991001-00000103”, “0?bypass,1”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:28] ExecIf(“SIP/9991001-00000103”, “1?Set(CONNECTEDLINE(num,i)=6475021488)”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf(“SIP/9991001-00000103”, “1?Set(CONNECTEDLINE(name,i)=CID:1xxxxx-client did-xxx)”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:30] ExecIf(“SIP/9991001-00000103”, “0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)xxxxx-client did-xxx)”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:31] GotoIf(“SIP/9991001-00000103”, “0?customtrunk”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:32] ExecIf(“SIP/9991001-00000103”, “0?Set(DIAL_TRUNK_OPTIONS=)”) in new stack
[2020-01-10 15:56:25] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@macro-dialout-trunk:33] Dial(“SIP/9991001-00000103”, “SIP/LUCID-EYET-Main/6475021488,300,Tb(func-apply-sipheaders^s^1,(2))”) in new stack
[2020-01-10 15:56:26] VERBOSE[9172][C-000000dd] app_dial.c: SIP/LUCID-EYET-Main-00000104 is making progress passing it to SIP/9991001-00000103
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] app_macro.c: Spawn extension (macro-dialout-trunk, s, 33) exited non-zero on ‘SIP/9991001-00000103’ in macro ‘dialout-trunk’
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Spawn extension (restrictedroute-c81e728d9d4c2f636f067f89cc14862c, 6475021488, 6) exited non-zero on ‘SIP/9991001-00000103’
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [h@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:1] Hangup(“SIP/9991001-00000103”, “”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Spawn extension (restrictedroute-c81e728d9d4c2f636f067f89cc14862c, h, 1) exited non-zero on ‘SIP/9991001-00000103’
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] app_stack.c: SIP/9991001-00000103 Internal Gosub(crm-hangup,s,1) start
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/9991001-00000103”, “Sending Hangup to CRM”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/9991001-00000103”, “HANGUP CAUSE: 16”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/9991001-00000103”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/9991001-00000103”, “MASTER CHANNEL: 1578689784.310 = 1578689784.310”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/9991001-00000103”, “0?return”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/9991001-00000103”, “__CRM_HANGUP=1”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/9991001-00000103”, “agi://127.0.0.1/sangomacrm.agi”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] res_agi.c: <SIP/9991001-00000103>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/9991001-00000103”, “”) in new stack
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] app_stack.c: Spawn extension (restrictedroute-c81e728d9d4c2f636f067f89cc14862c, h, 1) exited non-zero on ‘SIP/9991001-00000103’
[2020-01-10 15:56:42] VERBOSE[9172][C-000000dd] app_stack.c: SIP/9991001-00000103 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2020-01-10 15:56:43] NOTICE[2649] chan_sip.c: Received SIP subscribe for peer without mailbox: 9991001

--------tcpdump-----
OPTIONS sip:9991001@76.64.106.111:5060 SIP/2.0
Via: SIP/2.0/UDP Public-IP:5160;branch=z9hG4bK622f3fea
Max-Forwards: 70
From: “Unknown” sip:Unknown@Public-IP:5160;tag=as4b77e1a4
To: sip:9991001@76.64.106.111:5060
Contact: sip:Unknown@Public-IP:5160
Call-ID: 1718a478387794ef0ba935b24e9ca023@198.55.54.14:5160
CSeq: 102 OPTIONS
User-Agent: FPBX-15.0.16.38(16.6.2)
Date: Fri, 10 Jan 2020 20:33:25 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

SIP/2.0 200 OK
Via: SIP/2.0/UDP Public-IP:5160;branch=z9hG4bK622f3fea
From: “Unknown” sip:Unknown@Public-IP:5160;tag=as4b77e1a4
To: sip:9991001@76.64.106.111:5060;tag=1843662402
Call-ID: 1718a478387794ef0ba935b24e9ca023@Public-IP:5160
CSeq: 102 OPTIONS
Contact: sip:9991001@76.64.106.111:5060
Supported: 100rel, replaces, timer
User-Agent: Fanvil X7 1.12.5.1 0c383e30303f
Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE
Accept: application/sdp, message/sipfrag, application/dtmf-relay
Content-Length: 0

SIP/2.0 200 OK
Via: SIP/2.0/UDP 76.64.106.111:5060;branch=z9hG4bK3053341852565233749;received=76.64.106.111;rport=5060
From: 999-test sip:9991001@pbx14.voip.ithandsfree.net:5160;tag=3658326676
To: sip:6475021488@pbx14.voip.ithandsfree.net:5160;tag=as0b266560
Call-ID: 308704443437387-585162215520909@76.64.106.111
CSeq: 2 INVITE
Server: FPBX-15.0.16.38(16.6.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:6475021488@Public-IP:5160
P-Asserted-Identity: “CID:xxx-client DIDxxxx” sip:6475021488@pbx14.voip.ithandsfree.net
Content-Type: application/sdp
Content-Length: 440

v=0
o=root 1687146843 1687146843 IN IP4 Public-IP:
s=Asterisk PBX 16.6.2
c=IN IP4 Public-IP:
b=CT:384
t=0 0
m=audio 16724 RTP/AVP 0 8 102 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv
m=video 12512 RTP/AVP 117
a=rtpmap:117 H264/90000
a=fmtp:117 max-br=2000;profile-level-id=42801E
a=sendrecv
ACK sip:6475021488@Public-IP:5160 SIP/2.0
Via: SIP/2.0/UDP 76.64.106.111:5060;branch=z9hG4bK494584896910519574
From: 999-test sip:9991001@pbx14.voip.ithandsfree.net:5160;tag=3658326676
To: sip:6475021488@pbx14.voip.ithandsfree.net:5160;tag=as0b266560
Call-ID: 308704443437387-585162215520909@76.64.106.111
CSeq: 2 ACK
Contact: sip:9991001@76.64.106.111:5060
Max-Forwards: 70
User-Agent: Fanvil X7 1.12.5.1 0c383e30303f
Content-Length: 0

…BYE sip:6475021488@Public-IP:5160 SIP/2.0
Via: SIP/2.0/UDP 76.64.106.111:5060;branch=z9hG4bK20904541494261638;rport
From: 999-test sip:9991001@pbx14.voip.ithandsfree.net:5160;tag=3658326676
To: sip:6475021488@pbx14.voip.ithandsfree.net:5160;tag=as0b266560
Call-ID: 308704443437387-585162215520909@76.64.106.111
CSeq: 3 BYE
Contact: sip:9991001@76.64.106.111:5060
Max-Forwards: 70
User-Agent: Fanvil X7 1.12.5.1 0c383e30303f
Content-Length: 0

SIP/2.0 200 OK
Via: SIP/2.0/UDP 76.64.106.111:5060;branch=z9hG4bK20904541494261638;received=76.64.106.111;rport=5060
From: 999-test sip:9991001@pbx14.voip.ithandsfree.net:5160;tag=3658326676
To: sip:6475021488@pbx14.voip.ithandsfree.net:5160;tag=as0b266560
Call-ID: 308704443437387-585162215520909@76.64.106.111
CSeq: 3 BYE
Server: FPBX-15.0.16.38(16.6.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

Stewart1 · 2020-01-11 03:20:04 UTC

The Asterisk log appears to show the correct 416 number set as caller ID, but your tcpdump doesn’t show any of the communication with the trunking provider, so we don’t know whether it’s a trunk configuration issue or a problem at the provider.

For this, there is no need to use tcpdump; at the Asterisk command prompt type
sip set debug on
then make a test call. The SIP traces will appear interspersed in the regular Asterisk log.
Paste that at https://pastebin.freepbx.org and post the link here.

Also, post your outbound trunk settings.

BTW, according to https://apeiron.io/lrn , the 416 number ported to Iristel only yesterday at about 09:42 Toronto time, so it’s possible that your provider hasn’t set everything up properly.

rwize · 2020-01-11 05:50:53 UTC

Resolved:

So it looks like there has been some change with the latest Distro FreePBX as this issue is not happening to my other pbx’s.

So the resolution was to modify the SIP Trunk Outbound registration string in the following way

Original:

canreinvite=nonat
nat=yes
context=from-trunk
host=voip.itsvoiptime.com
secret=xxxxxxx
type=peer
username=xxxxxxxx
disallow=all
allow=ulaw&g729
fromuser=xxxxxxxxxxxxx
trustrpid=yes
sendrpid=yes
insecure=invite
qualify=yes

Modified: resolved the issue

username=xxxxxxx
type=peer
trustrpid=yes
sendrpid=yes
secret=xxxxxxx
qualify=yes
nat=yes
insecure=invite
host=voip.itsvoiptime.com
disallow=all
context=from-trunk
canreinvite=nonat
allow=ulaw&g729
removedfromuser=xxxxxxxxxxxremoved

It seems that the “fromuser=” entry was overriding any configured CID

I was able to see through my Telcom partner reseller portal what CID was showing and the CID matched the “fromuser=” entry. I figured since “username=” was already commented I didn’t need the “fromuser=” and I was right.

Hope this assists anyone.

Stewart1 · 2020-01-11 06:25:16 UTC

I’m glad that you got it working, but chan_sip has not been changed in ages; there must be some other difference.

Some trunking providers will accept caller ID in the From header (which is what you get if you don’t constrain it with fromuser). Others require an account number or main phone number in the From header, which is why the fromuser parameter is available.

If you are required to send something other than caller ID in From, the provider usually accepts the caller ID in the P-Asserted-Identity header, which is what
sendrpid=pai
gives you. A few providers will also respect the Remote-Party-ID header, which can be set by specifying
sendrpid=yes

BTW, why are you using chan_sip at all? – pjsip is simpler to set up and less likely to cause trouble.

rwize · 2020-01-11 06:53:24 UTC

Thanks for the good feedback.
I tried with this brand new setup to use pjsip however I could not get the trunk to register with sip trunk provider and so it was easy to setup the sip trunk. I would like to transition to using pjsip for the SIP trunks and endpoint connections but I would have to do more testing.

I have been running FreePBX installations for 5+ years and they generally just work and so I have not needed to dig into the technical files, so I am limited to tcpdump, cdr reports and reviewing log reports but in this case I could not find anything in those area that explained the issue. The issue was present right from the installation point.

Thanks gain for the feedback, I really value the technical sharing as it expands my internal kb

rwize · 2020-01-11 07:42:26 UTC

FYI, Just switch main trunks to being pjsip. The issue that I had original and again today is that the pjsip would register but inbound calls would not work.
Once I switch the Auth settings to be Outbound Auth and to Send Registration, inbound calling began to work.

I agree it is much simpler to setup once the tweaks are in

Thanks again, I look forward to replacing all Chan_Sip trunks with pjsip

Cheers.

AdHominem · 2020-01-11 07:42:33 UTC

This is almost certainly a provider issue.

Some providers use the SIP Header that is generated by the fromuser= field for Caller ID. Others don’t.

See this wiki article:

https://wiki.freepbx.org/display/F2/Trunk+Sample+Configurations

“8. If your outbound calls never have the correct Caller ID, delete the fromuser= line.”

This important information used to be in the main wiki page for the Trunks module, but the community manager moved it to a sub-page called “Trunk Sample Configurations” even though this information isn’t really related to a sample configuration.

system · 2020-01-18 07:42:36 UTC

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