Outbound route struggling with CID settings

michiganbroadband · March 25, 2024, 6:22pm

I am new to FreePBX but not new to Asterisk.
I have a simple static IP trunk configured between FreePBX and another Asterisk server on the LAN.
The outbound route only “works” if I manually set the CID to any numeric value on the route.
It does not work at all or even try to route the call if I leave this field blank.
I would expect that leaving it blank or even if I do not would allow the CID setting in the EXTENSION to override this.
If I try to set it in the Extension config for the extension in FreePBX it does not work - does not route the call
I get “all circuits are busy” audio message from FREEPBX.
Same problem if I leave it blank in the extension config.
It does not work by leaving it bank (I assume it would use a field in the SIP header) from the IP phone itself.
Repeat: it also does not work if I set it in the extension config within FreePBX.
It does work if I set any CID number in the CID field on the route.

I can of course get into more details as requested.
But is simply is failing the internal call logic and not routing if I try to have CID set in the extension config itself or try to just let it pass through from the SIP headers from the IP phone device itself.
But works fine if I overriede CID at the CID config field for the route.
Not working:
Calling=4701
Called=4400

Asterisk log from WEBUI during a failed route call. “allcircuits are busy” message heard at calling IP phone.
This is not complete due to post character limits.

11310[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:1] Macro("PJSIP/4701-00000064", "user-callerid,LIMIT,EXTERNAL,") in new stack
11311[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/4701-00000064", "TOUCH_MONITOR=1711390495.103") in new stack
11312[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/4701-00000064", "CHANCONTEXT=") in new stack
11313[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:3] Progress("PJSIP/4701-00000064", "") in new stack
11314[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/4701-00000064", "CHANCONTEXT=") in new stack
11315[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/4701-00000064", "CHANEXTENCONTEXT=4701-00000064") in new stack
11316[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:6] Set("PJSIP/4701-00000064", "CHANEXTEN=4701-00000064") in new stack
11317[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/4701-00000064", "CALLERID(number)=4701") in new stack
11318[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:8] Set("PJSIP/4701-00000064", "AMPUSER=4701") in new stack
11319[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:9] Set("PJSIP/4701-00000064", "HOTDESCKCHAN=4701-00000064") in new stack
11320[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/4701-00000064", "HOTDESKEXTEN=4701") in new stack
11321[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/4701-00000064", "HOTDESKCALL=0") in new stack
11322[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:12] ExecIf("PJSIP/4701-00000064", "0?Set(HOTDESKCALL=1)") in new stack
11323[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(name)=)") in new stack
11324[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("PJSIP/4701-00000064", "0?report") in new stack
11325[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("PJSIP/4701-00000064", "1?Set(REALCALLERIDNUM=4701)") in new stack
11326[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:16] Set("PJSIP/4701-00000064", "AMPUSER=4701") in new stack
11327[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/4701-00000064", "0?limit") in new stack
11328[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-user-callerid:18] 
11372[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [out@sub-record-check:1] NoOp("PJSIP/4701-00000064", "Outbound Recording Check from 4701 to 4400") in new stack
11373[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [out@sub-record-check:2] Set("PJSIP/4701-00000064", "RECMODE=dontcare") in new stack
11374[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [out@sub-record-check:3] ExecIf("PJSIP/4701-00000064", "1?Goto(routewins)") in new stack
11375[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx_builtins.c: Goto (sub-record-check,out,7)
11376[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [out@sub-record-check:7] Gosub("PJSIP/4701-00000064", "recordcheck,1(dontcare,out,4400)") in new stack
11377[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/4701-00000064", "Starting recording check against dontcare") in new stack
11378[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/4701-00000064", "dontcare") in new stack
11379[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
11380[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/4701-00000064", "") in new stack
11381[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [out@sub-record-check:8] Return("PJSIP/4701-00000064", "") in new stack
11382[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:3] ExecIf("PJSIP/4701-00000064", "0 ?Set(CDR(accountcode)=)") in new stack
11383[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:4] Set("PJSIP/4701-00000064", "_ROUTEID=1") in new stack
11384[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:5] Set("PJSIP/4701-00000064", "_ROUTENAME=4111") in new stack
11385[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:6] Set("PJSIP/4701-00000064", "MOHCLASS=default") in new stack
11386[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:7] Set("PJSIP/4701-00000064", "_CALLERIDNAMEINTERNAL=Steve Gladden") in new stack
11387[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:8] Set("PJSIP/4701-00000064", "_CALLERIDNUMINTERNAL=4701") in new stack
11388[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:9] Set("PJSIP/4701-00000064", "_EMAILNOTIFICATION=FALSE") in new stack
11389[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:10] Set("PJSIP/4701-00000064", "_NODEST=") in new stack
11390[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [4400@from-internal:11] Macro("PJSIP/4701-00000064", "dialout-trunk,1,4400,,off") in new stack
11391[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:1] Set("PJSIP/4701-00000064", "DIAL_TRUNK=1") in new stack
11392[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/4701-00000064", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack
11393[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/4701-00000064", "0?sub-pincheck,s,1()") in new stack
11394[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(num)=4701)") in new stack
11395[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf("PJSIP/4701-00000064", "0?disabletrunk,1") in new stack
11396[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:6] Set("PJSIP/4701-00000064", "DIAL_NUMBER=4400") in new stack
11397[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:7] Set("PJSIP/4701-00000064", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack
11398[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:8] Set("PJSIP/4701-00000064", "OUTBOUND_GROUP=OUT_1") in new stack
11399[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:9] Set("PJSIP/4701-00000064", "DIAL_TRUNK_OPTIONS=T") in new stack
11400[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf("PJSIP/4701-00000064", "1?nomax") in new stack
11401[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx_builtins.c: Goto (macro-dialout-trunk,s,12)
11402[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/4701-00000064", "0?skipoutcid") in new stack
11403[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:13] Macro("PJSIP/4701-00000064", "outbound-callerid,1") in new stack
11404[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp("PJSIP/4701-00000064", "4701") in new stack
11405[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/4701-00000064", "") in new stack
11406[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/4701-00000064", "off") in new stack
11407[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(name-pres)=)") in new stack
11408[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(num-pres)=)") in new stack
11409[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:6] Set("PJSIP/4701-00000064", "HOTDESCKCHAN=4701-00000064") in new stack
11410[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:7] Set("PJSIP/4701-00000064", "HOTDESKEXTEN=4701") in new stack
11411[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:8] Set("PJSIP/4701-00000064", "HOTDESKCALL=0") in new stack
11412[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:9] ExecIf("PJSIP/4701-00000064", "0?Set(HOTDESKCALL=1)") in new stack
11413[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:10] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(name)=)") in new stack
11414[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:11] Set("PJSIP/4701-00000064", "ALLOWTHISROUTE=NO") in new stack
11415[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:12] ExecIf("PJSIP/4701-00000064", "0?Set(ALLOWTHISROUTE=YES)") in new stack
11416[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:13] ExecIf("PJSIP/4701-00000064", "0?Hangup()") in new stack
11417[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:14] ExecIf("PJSIP/4701-00000064", "0?Set(REALCALLERIDNUM=4701)") in new stack
11418[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:15] ExecIf("PJSIP/4701-00000064", "0?Set(AMPUSER=4701)") in new stack
11419[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:16] GotoIf("PJSIP/4701-00000064", "1?normcid") in new stack
11420[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)
11421[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:20] Set("PJSIP/4701-00000064", "USEROUTCID=") in new stack
11422[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:21] Set("PJSIP/4701-00000064", "EMERGENCYCID=") in new stack
11423[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/4701-00000064", "0?Set(SCDEXT=YES)") in new stack
11424[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf("PJSIP/4701-00000064", "0?Set(EMERGENCYCID=)") in new stack
11425[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(name)=)") in new stack
11426[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:25] ExecIf("PJSIP/4701-00000064", "0?Set(EMERGENCYCID=)") in new stack
11427[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:26] Set("PJSIP/4701-00000064", "TRUNKOUTCID=") in new stack
11428[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:27] GotoIf("PJSIP/4701-00000064", "1?trunkcid") in new stack
11429[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx_builtins.c: Goto (macro-outbound-callerid,s,33)
11430[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:33] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(all)=)") in new stack
11431[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:34] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(all)=)") in new stack
11432[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:35] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(all)=)") in new stack
11433[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:36] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(all)=4701)") in new stack
11434[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:37] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(all)=4701)") in new stack
11435[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:38] Set("PJSIP/4701-00000064", "TIOHIDE=no") in new stack
11436[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:39] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(name-pres)=prohib_passed_screen)") in new stack
11437[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:40] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(num-pres)=prohib_passed_screen)") in new stack
11438[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:41] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(name-pres)=prohib_passed_screen)") in new stack
11439[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:42] ExecIf("PJSIP/4701-00000064", "0?Set(CALLERID(num-pres)=prohib_passed_screen)") in new stack
11440[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:43] Set("PJSIP/4701-00000064", "CDR(outbound_cnum)=4701") in new stack
11441[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-outbound-callerid:44] Set("PJSIP/4701-00000064", "CDR(outbound_cnam)=Steve Gladden") in new stack
11442[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/4701-00000064", "0?sub-flp-1,s,1()") in new stack
11443[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/4701-00000064", "OUTNUM=4400") in new stack
11444[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/4701-00000064", "custom=PJSIP") in new stack
11445[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/4701-00000064", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
11446[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/4701-00000064", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
11447[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:19] ExecIf("PJSIP/4701-00000064", "0?AGI(allowlist-autoadd.agi,)") in new stack
11448[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:20] Macro("PJSIP/4701-00000064", "dialout-trunk-predial-hook,") in new stack
11449[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/4701-00000064", "") in new stack
11450[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:21] GotoIf("PJSIP/4701-00000064", "0?skipcrm") in new stack
11451[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:22] Set("PJSIP/4701-00000064", "__CRM_DIRECTION=OUTBOUND") in new stack
11452[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:23] Set("PJSIP/4701-00000064", "__CRM_DESTINATION=4400") in new stack
11453[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:24] Set("PJSIP/4701-00000064", "__CRM_SOURCE=4701") in new stack
11454[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:25] AGI("PJSIP/4701-00000064", "agi://127.0.0.1/sangomacrm.agi") in new stack
11455[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] res_agi.c: <PJSIP/4701-00000064>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
11456[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:26] Set("PJSIP/4701-00000064", "CHANNEL(hangup_handler_push)=crm-hangup,s,1") in new stack
11457[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:27] NoOp("PJSIP/4701-00000064", "CRM Finished") in new stack
11458[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:28] GotoIf("PJSIP/4701-00000064", "0?bypass,1") in new stack
11459[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf("PJSIP/4701-00000064", "1?Set(CONNECTEDLINE(num,i)=4400)") in new stack
11460[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:30] ExecIf("PJSIP/4701-00000064", "1?Set(CONNECTEDLINE(name,i)=CID:4701)") in new stack
11461[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:31] ExecIf("PJSIP/4701-00000064", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)4701)") in new stack
11462[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:32] GotoIf("PJSIP/4701-00000064", "0?customtrunk") in new stack
11463[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:33] ExecIf("PJSIP/4701-00000064", "0?Set(DIAL_TRUNK_OPTIONS=)") in new stack
11464[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:34] Set("PJSIP/4701-00000064", "HASH(__SIPHEADERS,Alert-Info)=unset") in new stack
11465[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@macro-dialout-trunk:35] Dial("PJSIP/4701-00000064", "PJSIP/4400@blah,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^4400^4400^1^1711390495^Steve Gladden^4701)") in new stack
11466[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] app_stack.c: PJSIP/blah-00000065 Internal Gosub(func-apply-sipheaders,s,1(1)) start
11467[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/blah-00000065", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
11468[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/blah-00000065", "Applying SIP Headers to channel PJSIP/blah-00000065") in new stack
11469[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/blah-00000065", "localchan=blah-00000065") in new stack
11470[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/blah-00000065", "DialMCEXT=blah") in new stack
11471[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:5] Set("PJSIP/blah-00000065", "CHANNEL(hangup_handler_push)=app-missedcall-hangup,blah,1") in new stack
11472[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:6] Set("PJSIP/blah-00000065", "TECH=PJSIP") in new stack
11473[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:7] Set("PJSIP/blah-00000065", "SIPHEADERKEYS=Alert-Info") in new stack
11474[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:8] While("PJSIP/blah-00000065", "1") in new stack
11475[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:9] Set("PJSIP/blah-00000065", "sipheader=unset") in new stack
11476[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/blah-00000065", "1?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
11477[2024-03-25 14:14:55] ERROR[31685] res_pjsip_header_funcs.c: No headers had been previously added to this session.
11478[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/blah-00000065", "0?Set(sipheader=<http://127.0.0.1>;info=unset)") in new stack
11479[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:12] ExecIf("PJSIP/blah-00000065", "0?Set(sipheader=<http://127.0.0.1>unset)") in new stack
11480[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:13] ExecIf("PJSIP/blah-00000065", "0?Set(PJSIP_HEADER(add,Alert-Info)=unset)") in new stack
11481[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:14] EndWhile("PJSIP/blah-00000065", "") in new stack
11482[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:8] While("PJSIP/blah-00000065", "0") in new stack
11483[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [s@func-apply-sipheaders:15] Return("PJSIP/blah-00000065", "") in new stack
11484[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] app_stack.c: Spawn extension (from-pstn, 4400, 1) exited non-zero on 'PJSIP/blah-00000065'
11485[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] app_stack.c: PJSIP/blah-00000065 Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=
11486[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] app_dial.c: Called PJSIP/4400@blah
11487[2024-03-25 14:14:55] ERROR[31685] res_pjsip_outbound_authenticator_digest.c: Endpoint: 'blah': There were no auth ids available
11488[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] app_stack.c: PJSIP/blah-00000065 Internal Gosub(app-missedcall-hangup,blah,1) start
11489[2024-03-25 14:14:55] VERBOSE[12298][C-0000003e] pbx.c: Executing [blah@app-missedcall-hangup:1] NoOp("PJSIP/blah-00000065", "Dialed: blah") in new stack
...

michiganbroadband · March 25, 2024, 6:22pm

Had to cut out much of the log (32000) char limit in posting.

Stewart1 · March 25, 2024, 8:51pm

Confirm that the Outbound CID for the extension is properly formatted, for example:
"John Doe" <12125561212>
with the number in the format that the provider requires.

Paste the Asterisk log for the call at pastebin.com and post the link here.j

michiganbroadband · March 25, 2024, 8:55pm

I’ll try that sir.
I haven’t thought that would matter, I’m not sending any of these out to an Internet carrier/provider.
But I get it that FreePBX might not like the format for some reason locally and it’s not going anywhere.
I am also expecting what is coming from the IP phone itself is already properly formatted.
Which I could also check further on.
Also the IP phone is in a configuation state that has always worked find with my other systems.
In terms of what it is sending out in the SIP INVITEs.
-sg

Stewart1 · March 25, 2024, 9:03pm

The caller information from the calling phone is used only to identify the extension. On an Intracompany trunk, the extension number is used as caller ID. Is this call intended to go out on an Intracompany trunk to an extension on another PBX of yours?

michiganbroadband · March 25, 2024, 9:06pm

Yes, that worked putting it into the Extension CID.
I guess It is being picky about something coming from the phone itself.
It’s also being picky about that format when entered for the extension.
I can certainly deal with that.
I’ll dig deeper into all of that.
It’s nice to see it working.

michiganbroadband · March 25, 2024, 9:10pm

Yes sorta. Right now it’s only intended for testing.
And yes it’s going over in internal only SIP trunk to another older Asterisk18 PBX.

michiganbroadband · March 25, 2024, 9:14pm

I’m using this to familiarize myself with FreePBX.
This is the first FreePBX I have ever spun up ever.
I’m all of about five hours into it.
It’s also my first dive into using pjsip.
I’m way behind the times and still have chan_sip in production everywhere with manually compiled and configured Asterisk servers.
I’ve never yet done anything cool like realtime database web interfaces etc with our servers.
Call me lame, but they have served very well for a long time

michiganbroadband · March 25, 2024, 9:39pm

Now it’s fighting me and not allowing me to set the CID to the numeric number that matches either the inbound route destination or the extension number itself.
Will not allow outbound call.
If I plug ANY other number aside from this it works.
Some kind of conflict I am not expecting.
`“Testing” <4701> won;t allow outbound to happen (same all circuits busy message).
Inbound to 4701 works.

michiganbroadband · March 25, 2024, 9:47pm

I think we are actually back to the original problem.
As it was probably setting it to 4701 as it was before.
Now with properly formatting it is failing the same way but only when CID = “Testing” <4701>
If I plug any other number in there EXCEPT 4701 it works as expected.

Stewart1 · March 25, 2024, 9:52pm

So paste a log, including pjsip logger, of a failing call.

michiganbroadband · March 25, 2024, 10:15pm

Sorry I’m new to FreePBX.
Where is this log located?
And am guessing have to turn on debug or something for pjsip?
Or is default logging level good enough?
Also there is a message size limit here.
The entire failed call I posted earlier from the GUI defaults to “full” I’m guessing that is everything in the dropdown list?
Also withing the gui dropdown I do not see a pjsip option.
So I guess I need help in getting the logging info you are asking for.
Thanks!

michiganbroadband · March 25, 2024, 10:28pm

Via: SIP/2.0/UDP 10.73.73.7:5060;rport;branch=z9hG4bKPjb47082c0-55f0-4f4e-85cc-bdfdb22de38f
From: "testing" <sip:[email protected]>;tag=3c1ff16b-0853-4316-9988-af56998b8d9f
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 346aba9c-6f32-4577-a8a4-8e781f474d0c
CSeq: 22239 INVITE
Allow: OPTIONS, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub, histinfo
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: FPBX-16.0.40.7(18.20.2)
Content-Type: application/sdp
Content-Length:   335

v=0
o=- 1303240665 1303240665 IN IP4 10.73.73.7
s=Asterisk
c=IN IP4 10.73.73.7
t=0 0
m=audio 11236 RTP/AVP 0 8 9 3 111 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2024-03-25 18:21:39] VERBOSE[2270] res_pjsip_logger.c: <--- Received SIP response (579 bytes) from UDP:10.73.73.5:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.73.73.7:5060;branch=z9hG4bKPjb47082c0-55f0-4f4e-85cc-bdfdb22de38f;received=10.73.73.7;rport=5060
From: "testing" <sip:[email protected]>;tag=3c1ff16b-0853-4316-9988-af56998b8d9f
To: <sip:[email protected]>;tag=as29a325bc
Call-ID: 346aba9c-6f32-4577-a8a4-8e781f474d0c
CSeq: 22239 INVITE
Server: Asterisk PBX 16.4.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="52a4fd82"
Content-Length: 0


[2024-03-25 18:21:39] VERBOSE[2804] res_pjsip_logger.c: <--- Transmitting SIP request (394 bytes) to UDP:10.73.73.5:5060 --->
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.73.73.7:5060;rport;branch=z9hG4bKPjb47082c0-55f0-4f4e-85cc-bdfdb22de38f
From: "testing" <sip:[email protected]>;tag=3c1ff16b-0853-4316-9988-af56998b8d9f
To: <sip:[email protected]>;tag=as29a325bc
Call-ID: 346aba9c-6f32-4577-a8a4-8e781f474d0c
CSeq: 22239 ACK
Max-Forwards: 70
User-Agent: FPBX-16.0.40.7(18.20.2)
Content-Length:  0


[2024-03-25 18:21:39] ERROR[2804] res_pjsip_outbound_authenticator_digest.c: Endpoint: 'blah': There were no auth ids available
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] app_stack.c: PJSIP/blah-0000009c Internal Gosub(app-missedcall-hangup,blah,1) start
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:1] NoOp("PJSIP/blah-0000009c", "Dialed: blah") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:2] NoOp("PJSIP/blah-0000009c", "Caller: 4701") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:3] GotoIf("PJSIP/blah-0000009c", "0?exit") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:4] Set("PJSIP/blah-0000009c", "EXTENNUM=blah") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:5] Set("PJSIP/blah-0000009c", "FEXTENNUM=blah") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:6] GotoIf("PJSIP/blah-0000009c", "0?exit") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:7] AGI("PJSIP/blah-0000009c", "agi://127.0.0.1/missedcallnotify.php,blah,,blah,0,,PJSIP/blah-0000009c,,,,") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] res_agi.c: <PJSIP/blah-0000009c>AGI Script agi://127.0.0.1/missedcallnotify.php completed, returning 0
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [blah@app-missedcall-hangup:8] Return("PJSIP/blah-0000009c", "") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] app_stack.c: Spawn extension (from-pstn, 4400, 1) exited non-zero on 'PJSIP/blah-0000009c'
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] app_stack.c: PJSIP/blah-0000009c Internal Gosub(app-missedcall-hangup,blah,1) complete GOSUB_RETVAL=
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s@macro-dialout-trunk:36] NoOp("PJSIP/4701-0000009b", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 21") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s@macro-dialout-trunk:37] GotoIf("PJSIP/4701-0000009b", "0?continue,1:s-CHANUNAVAIL,1") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("PJSIP/4701-0000009b", "RC=21") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("PJSIP/4701-0000009b", "21,1") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx_builtins.c: Goto (macro-dialout-trunk,21,1)
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [21@macro-dialout-trunk:1] Goto("PJSIP/4701-0000009b", "continue,1") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [continue@macro-dialout-trunk:1] NoOp("PJSIP/4701-0000009b", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 21 - failing through to other trunks") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [continue@macro-dialout-trunk:2] ExecIf("PJSIP/4701-0000009b", "1?Set(CALLERID(number)=4701)") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [4400@from-internal:12] Macro("PJSIP/4701-0000009b", "outisbusy,") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s@macro-outisbusy:1] Progress("PJSIP/4701-0000009b", "") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s@macro-outisbusy:2] GotoIf("PJSIP/4701-0000009b", "0?emergency,1") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s@macro-outisbusy:3] GotoIf("PJSIP/4701-0000009b", "0?intracompany,1") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] pbx.c: Executing [s@macro-outisbusy:4] Playback("PJSIP/4701-0000009b", "all-circuits-busy-now&please-try-call-later, noanswer") in new stack
[2024-03-25 18:21:39] VERBOSE[25148][C-0000005c] file.c: <PJSIP/4701-0000009b> Playing 'all-circuits-busy-now.ulaw' (language 'en')
[2024-03-25 18:21:40] VERBOSE[2804] res_pjsip_logger.c: <--- Transmitting SIP response (928 bytes) to UDP:10.73.73.100:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 10.73.73.100;rport=5060;received=10.73.73.100;branch=z9hG4bK259e8c18D0C052E7
Call-ID: e5c96dde49e6d017443bb2ad8d1f5425
From: "SteveG" <sip:[email protected]>;tag=C5444D64-F513ACC3
To: <sip:[email protected];user=phone>;tag=356272ad-9b4b-4cf0-958b-31a0adda82f6
CSeq: 2 INVITE
Server: FPBX-16.0.40.7(18.20.2)
Allow: OPTIONS, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, MESSAGE, REFER
Contact: <sip:10.73.73.7:5060>
P-Asserted-Identity: "CID:4701" <sip:[email protected];user=phone>
Content-Type: application/sdp
Content-Length:   307

v=0
o=- 1711405300 1711405302 IN IP4 10.73.73.7
s=Asterisk
c=IN IP4 10.73.73.7
t=0 0
m=audio 11246 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
m=video 0 RTP/AVP 109 34

[2024-03-25 18:21:41] VERBOSE[25148][C-0000005c] file.c: <PJSIP/4701-0000009b> Playing 'please-try-call-later.ulaw' (language 'en')
^C

michiganbroadband · March 25, 2024, 10:31pm

[2024-03-25 18:21:39] ERROR[2804] res_pjsip_outbound_authenticator_digest.c: Endpoint: 'blah': There were no auth ids available

The trunk is not set to authenticate in either direction but I am noticing these.
Pretty sure it shows up in the calls that work as well
I can double check.

[email protected] is the destination being “called” which is never happening due to the route failure.

But if I change the CID to ANYTHING else other than 4701 (itself) the call is routed and works.

david55 · March 25, 2024, 11:12pm

This sounds like you are using chan_sip on the other Asterisk, have an extension 4701 on it, and have used type=friend for that extension. In that case the call will be matched based on the 4701, in the From user.

This won’t happen with chan_pjisip, type=peer, or you avoid the extension number clash.

type=friend is overused on chan_sip configuration because people don’t understand the rules, there is a lot of misinformation, and people copy and paste configuration, most of which have a lot of bad practice in them.

michiganbroadband · March 26, 2024, 7:11pm

Yes it was the existence of the friend in the old system I thought I had verbose enough logging on at the console and it looked like nothing was coming in at all. the pjsip capture/log revealed that it was indeed sending the INVITE. I then turned up the logging. and immediately got rid of the friend on the old system. First time I have ran into something like this.
And that was my problem all-along. everything else works now as expected and the phone itself can set caller CID and it gets passed along as expected earlier if I configure it to.
Thanks!

system · April 2, 2024, 7:12pm

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