Follow-me to external number failing

renrick · April 25, 2017, 12:58am

Hello everyone. So I have FreePBX 13.0.190.19. All my trunks are pjsip as I realize that ever since I installed this box I am having problems with sip trunks so I figured maybe this new version of asterisk does not like sip very well as I have spent an entire day trying to get sip trunks working which I used on elastix in the past, vicidial, and an older version of freepbx and everything work. But not on this version of freepbx. So I am back to using pjsip for all my trunks.

I have 2 analog trunks coming in via grandstream 4104 defined as 1001 and 1002.
I have 4 individial GSM Trunks to the pbx from openvox. Lets call them GSM1-4. I can place incoming calls and outgoing calls on any of the 6 trunks using different prefix for the trunk I want to dial out on.

If I receive a call on GSM1 I forward that call to extension 2150. If there is no answer I have follow me configured to call my cell number using trunk GSM2. The call does not go through. I see a message in the CLI that all circuits are busy now and the call just drops.

The strange thing is if I use one of my analog trunks from my grandstream device to send out the follow me call everything works. I just can’t figure out why it doesn’t work using my GSM Trunk.

Also if I dial from one extension to 2150 the call goes out using the follow me using GSM2.

Scenario 1: inbound call from cell number 734-7549 to 683-7425. Extension rings but follow me failed.

Some lines omitted because of limit.

[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:1] Set("PJSIP/4824775-00000026", "__DIRECTION=INBOUND") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:2] Gosub("PJSIP/4824775-00000026", "sub-record-check,s,1(in,6837425,dontcare)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/4824775-00000026", "0?initialized") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/4824775-00000026", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/4824775-00000026", "NOW=1493079834") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/4824775-00000026", "__DAY=24") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/4824775-00000026", "__MONTH=04") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/4824775-00000026", "__YEAR=2017") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/4824775-00000026", "__TIMESTR=20170424-202354") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/4824775-00000026", "__FROMEXTEN=unknown") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/4824775-00000026", "__MON_FMT=wav") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/4824775-00000026", "Recordings initialized") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/4824775-00000026", "0?Set(ARG3=dontcare)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/4824775-00000026", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/4824775-00000026", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/4824775-00000026", "2?checkaction") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/4824775-00000026", "1?sub-record-check,in,1") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [in@sub-record-check:1] NoOp("PJSIP/4824775-00000026", "Inbound Recording Check to 6837425") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [in@sub-record-check:2] Set("PJSIP/4824775-00000026", "FROMEXTEN=unknown") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [in@sub-record-check:3] ExecIf("PJSIP/4824775-00000026", "7?Set(FROMEXTEN=6837425)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [in@sub-record-check:4] Gosub("PJSIP/4824775-00000026", "recordcheck,1(dontcare,in,6837425)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/4824775-00000026", "Starting recording check against dontcare") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/4824775-00000026", "dontcare") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/4824775-00000026", "") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [in@sub-record-check:5] Return("PJSIP/4824775-00000026", "") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:3] Gosub("PJSIP/4824775-00000026", "app-blacklist-check,s,1()") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("PJSIP/4824775-00000026", "0?blacklisted") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/4824775-00000026", "CALLED_BLACKLIST=1") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/4824775-00000026", "") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:4] Set("PJSIP/4824775-00000026", "__FROM_DID=6837425") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:5] Set("PJSIP/4824775-00000026", "CDR(did)=6837425") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:6] ExecIf("PJSIP/4824775-00000026", "0 ?Set(CALLERID(name)=6837425)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:7] Set("PJSIP/4824775-00000026", "__MOHCLASS=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:8] Set("PJSIP/4824775-00000026", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [6837425@from-pstn:9] GotoIf("PJSIP/4824775-00000026", "1?post-reverse-charge") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:2] Set("PJSIP/4824775-00000026", "DIAL_OPTIONS=TtrI") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:3] Set("PJSIP/4824775-00000026", "CONNECTEDLINE(num,i)=2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:4] Gosub("PJSIP/4824775-00000026", "sub-presencestate-display,s,1(2150)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-presencestate-display:1] Goto("PJSIP/4824775-00000026", "state-not_set,1") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (sub-presencestate-display,state-not_set,1)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [state-not_set@sub-presencestate-display:1] Set("PJSIP/4824775-00000026", "PRESENCESTATE_DISPLAY=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [state-not_set@sub-presencestate-display:2] Return("PJSIP/4824775-00000026", "") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:5] Set("PJSIP/4824775-00000026", "CONNECTEDLINE(name)=The Boss") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:6] Set("PJSIP/4824775-00000026", "FM_DIALSTATUS=NOT_INUSE") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:7] Set("PJSIP/4824775-00000026", "__EXTTOCALL=2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:8] Set("PJSIP/4824775-00000026", "__PICKUPMARK=2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:9] Macro("PJSIP/4824775-00000026", "blkvm-setifempty,") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("PJSIP/4824775-00000026", "1?init") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:10] GotoIf("PJSIP/4824775-00000026", "1?skipov") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (followme-sub,2150,13)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:13] Set("PJSIP/4824775-00000026", "RRNODEST=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:14] Set("PJSIP/4824775-00000026", "__NODEST=2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:15] GosubIf("PJSIP/4824775-00000026", "0?sub-fmsetcid,s,1()") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:16] GotoIf("PJSIP/4824775-00000026", "1?skipprepend") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (followme-sub,2150,18)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:18] Set("PJSIP/4824775-00000026", "RecordMethod=Group") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:19] Gosub("PJSIP/4824775-00000026", "sub-record-check,s,1(exten,2150,)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/4824775-00000026", "7?initialized") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (sub-record-check,s,10)
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:23] Set("PJSIP/4824775-00000026", "STRATEGY=ringall-prim") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:24] Set("PJSIP/4824775-00000026", "RVOL=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:25] GotoIf("PJSIP/4824775-00000026", "0?skipsimple") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:26] GotoIf("PJSIP/4824775-00000026", "0 ?skipsimple") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [2150@followme-sub:27] Macro("PJSIP/4824775-00000026", "simple-dial,2150,7") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-simple-dial:1] Set("PJSIP/4824775-00000026", "__EXTTOCALL=2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-simple-dial:2] Set("PJSIP/4824775-00000026", "RT=7") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-simple-dial:3] Set("PJSIP/4824775-00000026", "CFUEXT=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-simple-dial:4] Set("PJSIP/4824775-00000026", "CFBEXT=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-simple-dial:5] Set("PJSIP/4824775-00000026", "CWI_TMP=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-simple-dial:6] Macro("PJSIP/4824775-00000026", "dial-one,7,TtrI,2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-one:1] Set("PJSIP/4824775-00000026", "DEXTEN=2150") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-one:2] ExecIf("PJSIP/4824775-00000026", "0?Set(EXTTOCALL=2150)") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-one:3] Set("PJSIP/4824775-00000026", "DIALSTATUS_CW=") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-one:4] GosubIf("PJSIP/4824775-00000026", "0?screen,1()") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-one:5] GosubIf("PJSIP/4824775-00000026", "0?cf,1()") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-one:6] GotoIf("PJSIP/4824775-00000026", "1?skip1") in new stack
[2017-04-24 20:23:54] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (macro-dial-one,s,9)
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Caller ID name is '+18687347549' number is '6837425'**
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: CW Ignore is:**
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: CF Ignore is:**
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: CW IN_USE/BUSY is: 1**
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Methodology of ring is 'ringall-prim'**
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Added extension 2150 to extension map**
**[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Added extension 423366028# to extension map**
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Extension 2150 cf is disabled
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Extension 423366028# cf is disabled
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Extension 2150 do not disturb is disabled
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Extension 2150 has ExtensionState: 0
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Discovered PJSIP Endpoint PJSIP/2150
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Ended up with real PJSIP Dial string PJSIP/2150/sip:[email protected]:5060
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/2150 to 6837425
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: dialparties.agi: Filtered ARG3: 2150-423366028
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] res_agi.c: <PJSIP/4824775-00000026>AGI Script dialparties.agi completed, returning 0
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:9] NoOp("PJSIP/4824775-00000026", "Returned from dialparties with groups to dial") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:10] Set("PJSIP/4824775-00000026", "LOOPCNT=2") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:11] Set("PJSIP/4824775-00000026", "ITER=1") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("PJSIP/4824775-00000026", "EXTTOCALL=2150") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("PJSIP/4824775-00000026", "Working with 2150") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:14] ExecIf("PJSIP/4824775-00000026", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:15] ExecIf("PJSIP/4824775-00000026", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:16] Set("PJSIP/4824775-00000026", "ITER=2") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:17] GotoIf("PJSIP/4824775-00000026", "1?ndloopbegin") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("PJSIP/4824775-00000026", "EXTTOCALL=423366028") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("PJSIP/4824775-00000026", "Working with 423366028") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:14] ExecIf("PJSIP/4824775-00000026", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:15] ExecIf("PJSIP/4824775-00000026", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:16] Set("PJSIP/4824775-00000026", "ITER=3") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:17] GotoIf("PJSIP/4824775-00000026", "0?ndloopbegin") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:18] Macro("PJSIP/4824775-00000026", "dial-ringall-predial-hook,") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("PJSIP/4824775-00000026", "") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@macro-dial:19] Dial("PJSIP/4824775-00000026", "PJSIP/2150/sip:[email protected]:5060&Local/423366028@from-internal/n,20,trIM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_stack.c: PJSIP/2150-00000028 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("PJSIP/2150-00000028", "Applying SIP Headers to channel") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("PJSIP/2150-00000028", "SIPHEADERKEYS=") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("PJSIP/2150-00000028", "0") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_while.c: Jumping to priority 7
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("PJSIP/2150-00000028", "") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_stack.c: Spawn extension (from-internal, 2150, 1) exited non-zero on 'PJSIP/2150-00000028'
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_stack.c: PJSIP/2150-00000028 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_stack.c: Local/423366028@from-internal-00000006;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("Local/423366028@from-internal-00000006;1", "Applying SIP Headers to channel") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("Local/423366028@from-internal-00000006;1", "SIPHEADERKEYS=") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("Local/423366028@from-internal-00000006;1", "0") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_while.c: Jumping to priority 7
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("Local/423366028@from-internal-00000006;1", "") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_stack.c: Spawn extension (from-internal, 2150, 1) exited non-zero on 'Local/423366028@from-internal-00000006;1'
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_stack.c: Local/423366028@from-internal-00000006;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_dial.c: Called PJSIP/2150/sip:[email protected]:5060
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_dial.c: Called Local/423366028@from-internal/n
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_dial.c: Connected line update to PJSIP/4824775-00000026 prevented.
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [423366028@from-internal:1] Macro("Local/423366028@from-internal-00000006;2", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:1] Set("Local/423366028@from-internal-00000006;2", "TOUCH_MONITOR=1493079842.54") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:2] Set("Local/423366028@from-internal-00000006;2", "AMPUSER=6837425") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("Local/423366028@from-internal-00000006;2", "0?report") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("Local/423366028@from-internal-00000006;2", "1?Set(REALCALLERIDNUM=6837425)") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:5] Set("Local/423366028@from-internal-00000006;2", "AMPUSER=") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("Local/423366028@from-internal-00000006;2", "0?limit") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:7] Set("Local/423366028@from-internal-00000006;2", "AMPUSERCIDNAME=") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("Local/423366028@from-internal-00000006;2", "1?report") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("Local/423366028@from-internal-00000006;2", "1?continue") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:29] Set("Local/423366028@from-internal-00000006;2", "CALLERID(number)=6837425") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:30] Set("Local/423366028@from-internal-00000006;2", "CALLERID(name)=+18687347549") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("Local/423366028@from-internal-00000006;2", "0?cnum") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:32] Set("Local/423366028@from-internal-00000006;2", "CDR(cnam)=+18687347549") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:33] Set("Local/423366028@from-internal-00000006;2", "CDR(cnum)=6837425") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-user-callerid:34] Set("Local/423366028@from-internal-00000006;2", "CHANNEL(language)=en") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [423366028@from-internal:2] Gosub("Local/423366028@from-internal-00000006;2", "sub-record-check,s,1(out,423366028,dontcare)") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:1] GotoIf("Local/423366028@from-internal-00000006;2", "0?initialized") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:2] Set("Local/423366028@from-internal-00000006;2", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:3] Set("Local/423366028@from-internal-00000006;2", "NOW=1493079842") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:4] Set("Local/423366028@from-internal-00000006;2", "__DAY=24") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:5] Set("Local/423366028@from-internal-00000006;2", "__MONTH=04") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:6] Set("Local/423366028@from-internal-00000006;2", "__YEAR=2017") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:7] Set("Local/423366028@from-internal-00000006;2", "__TIMESTR=20170424-202402") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:8] Set("Local/423366028@from-internal-00000006;2", "__FROMEXTEN=6837425") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:9] Set("Local/423366028@from-internal-00000006;2", "__MON_FMT=wav") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@sub-record-check:10] NoOp("Local/423366028@from-internal-00000006;2", "Recordings initialized") in new stack

[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [423366028@from-internal:8] Macro("Local/423366028@from-internal-00000006;2", "outisbusy,") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-outisbusy:1] Progress("Local/423366028@from-internal-00000006;2", "") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-outisbusy:2] GotoIf("Local/423366028@from-internal-00000006;2", "0?emergency,1") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-outisbusy:3] GotoIf("Local/423366028@from-internal-00000006;2", "0?intracompany,1") in new stack
[2017-04-24 20:24:02] VERBOSE[16141][C-00000017] app_dial.c: Local/423366028@from-internal-00000006;1 is making progress passing it to PJSIP/4824775-00000026
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-outisbusy:4] Playback("Local/423366028@from-internal-00000006;2", "all-circuits-busy-now&pls-try-call-later, noanswer") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] file.c: <Local/423366028@from-internal-00000006;2> Playing 'all-circuits-busy-now.ulaw' (language 'en')
[2017-04-24 20:24:04] VERBOSE[16183][C-00000017] file.c: <Local/423366028@from-internal-00000006;2> Playing 'pls-try-call-later.ulaw' (language 'en')
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-outisbusy:5] Congestion("Local/423366028@from-internal-00000006;2", "20") in new stack
[2017-04-24 20:24:06] VERBOSE[16141][C-00000017] app_dial.c: Local/423366028@from-internal-00000006;1 is circuit-busy
[2017-04-24 20:24:06] WARNING[16183][C-00000017] channel.c: Prodding channel 'Local/423366028@from-internal-00000006;2' failed
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] app_macro.c: Spawn extension (macro-outisbusy, s, 5) exited non-zero on 'Local/423366028@from-internal-00000006;2' in macro 'outisbusy'
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Spawn extension (from-internal, 423366028, 8) exited non-zero on 'Local/423366028@from-internal-00000006;2'
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Executing [h@from-internal:1] Macro("Local/423366028@from-internal-00000006;2", "hangupcall") in new stack
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("Local/423366028@from-internal-00000006;2", "1?theend") in new stack
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("Local/423366028@from-internal-00000006;2", "0?Set(CDR(recordingfile)=)") in new stack
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Executing [s@macro-hangupcall:4] Hangup("Local/423366028@from-internal-00000006;2", "") in new stack
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'Local/423366028@from-internal-00000006;2' in macro 'hangupcall'
[2017-04-24 20:24:06] VERBOSE[16183][C-00000017] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'Local/423366028@from-internal-00000006;2'
[2017-04-24 20:24:07] VERBOSE[16141][C-00000017] app_macro.c: Spawn extension (macro-dial, s, 19) exited non-zero on 'PJSIP/4824775-00000026' in macro 'dial'
[2017-04-24 20:24:07] VERBOSE[16141][C-00000017] pbx.c: Spawn extension (followme-sub, 2150, 37) exited non-zero on 'PJSIP/4824775-00000026'

Scenario 2: Call from extension 3367 to extension 2150 – Follow-me to cell number 336-6028 works outgoing on GSM2.

Scenario 3. Follow me trunk set to analog trunk. Call rings through to follow me number.

Can anyone help me in determining why it not working on my GSM Trunk. What am I missing ?

danielf · April 25, 2017, 10:00am

Hello @renrick,

Did you tried replacing the number 423366028 with another number just to be sure that it is not related to this specific number?

Thank you,

Daniel Friedman
Trixton LTD.

lgaetz · April 25, 2017, 10:24am

Looking at your call log with some lines removed for clarity:

[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [423366028@from-internal:1] Macro("Local/423366028@from-internal-00000006;2", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [423366028@from-internal:2] Gosub("Local/423366028@from-internal-00000006;2", "sub-record-check,s,1(out,423366028,dontcare)") in new stack
[2017-04-24 20:24:02] VERBOSE[16183][C-00000017] pbx.c: Executing [423366028@from-internal:8] Macro("Local/423366028@from-internal-00000006;2", "outisbusy,") in new stack

The outbound call appears to hit an outbound route, executes priority 1 and 2 as expected but then jumps to priority 8 which is unexpected. What is the output from:

asterisk -x "dialplan show 423366028@from-internal"

renrick · April 25, 2017, 7:56pm

@ Daniel. No I did not. The reason is that it worked from using a trunk from my grandstream box. Also If I dial ext 2150 from another extension the call will ring and follow-through to this number. 42 is my steering digit to use this particular trunk. If I change this to 83366028 the call will go through using trunk 1001 from my grandstream gateway if I dial from external straight to my cell phone. What I didn’t try is another trunk from the openvox GSM gateway. I figured it may not make a difference but I can give it a shot and post back the result. Thanks for your response.

renrick · April 25, 2017, 7:59pm

Thanks for your response @lgaetz. Will get back to you later.

danielf · April 25, 2017, 8:00pm

Hi @renrick,

What about what @lgaetz asked from you? we need to verify the source of the problem.

asterisk -x "dialplan show 423366028@from-internal"

Thank you,

Daniel Friedman
Trixton LTD

renrick · April 25, 2017, 8:04pm

Yes I saw that but I don’t have the access to the box to run that code now. Actually from the gui I did run it and got this. Not sure if its the same from the console. So for now this is what I am seeing when I run this from the gui remotely. Will have to confirm if there are additional data when I get in front the box as for some reason I don’t have ssh access.

[ Included context 'outrt-6' created by 'pbx_config' ]
  '_42.' =>         1. Macro(user-callerid,LIMIT,EXTERNAL,)       [pbx_config]
                    2. Gosub(sub-record-check,s,1(out,${EXTEN},dontcare)) [pbx_config]
                    3. ExecIf($[ "${CALLEE_ACCOUNCODE}" != "" ] ?Set(CDR(accountcode)=${CALLEE_ACCOUNCODE})) [pbx_config]
                    4. Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})}) [pbx_config]
                    5. ExecIf($["${KEEPCID}"!="TRUE" & ${LEN(${TRUNKCIDOVERRIDE})}=0]?Set(TRUNKCIDOVERRIDE=3254006)) [pbx_config]
                    6. Set(_NODEST=)                              [pbx_config]
                    7. Macro(dialout-trunk,2,${EXTEN:2},,off)     [pbx_config]
                    8. Macro(outisbusy,)                          [pbx_config]

[ Included context 'bad-number' created by 'pbx_config' ]
  '_X.' =>          1. ResetCDR()                                 [pbx_config]
                    2. NoCDR()                                    [pbx_config]
                    3. Progress()                                 [pbx_config]
                    4. Wait(1)                                    [pbx_config]
                    5. Playback(silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer) [pbx_config]
                    6. Wait(1)                                    [pbx_config]
                    7. Congestion(20)                             [pbx_config]
                    8. Hangup()                                   [pbx_config]

-= 2 extensions (16 priorities) in 2 contexts. =-

renrick · April 25, 2017, 8:08pm

HI @lgaetz Is the output above re response to @danielf last question what you were expecting from the command?

danielf · April 25, 2017, 8:30pm

Hi @renrick,

It looks ok from the Asterisk side. I would try to dial another number from this trunk or to switch to another trunk on your gateway. It seems that you have some sort of restriction from the gateway or your provider.

I would also have checked the following:

a caller id restriction.
an account restriction from the provider.
a gateway issue.

Thank you,

Daniel Friedman
Trixton LTD.

renrick · April 25, 2017, 11:46pm

Hi @danielf

So I changed to another trunk as you suggested. Also I used a different number and got the same results. While I was out today I got a follow me call to my 336 number using one of my analog trunk on the grandstream box. I am not sure if there is something specific in the log which will point to the problem. Thing is I am not sure what exactly to check for. Strange thing is the very same extension 2150 is sending out the call using a different trunk and if I issue a steering code of 42 or 43 it will grab a trunk and send out the call without any problem. Do you require any additional info to help me to troubleshoot?

Cheers.

danielf · April 26, 2017, 5:52am

Hello @renrick,

I will need to check the logs. If you are using pjsip open the sip logger pjsip set logger on and send me the output when you try to make an incoming call.

Thank you,

Daniel Friedman
Trixton LTD.

renrick · April 26, 2017, 12:11pm

Hi @danielf,

So I enabled pjsip logging. Where is the output captured?. I expected to find it in var/log/asterisk/pjsip.log Thanks again for your interest in helping me solve this issue.

danielf · April 26, 2017, 12:17pm

Hello @renrick,

I forgot to write you the on flag to turn it on. You need to enable verbosity and the sip logger in order to see it in the Asterisk console:

core set verbose 4
pjsip set logger on

Then you will start see the logger lines on the screen (Asterisk console).
Copy and paste the lines to here when you dial to the PBX.

Then turn the logging off:

core set verbose 0
pjsip set logger off

Thank you,

Daniel Friedman
Trixton LTD.

renrick · April 26, 2017, 1:54pm

Hi @danielf

I hope I got this correct. This is what I got from the logger.

To: sip:[email protected]
Call-ID: [email protected]:5060
CSeq: 102 CANCEL
User-Agent: VoxStack Wireless Gateway
Content-Length: 0

<— Transmitting SIP response (380 bytes) to UDP:172.20.1.150:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.150:5060;rport=5060;received=172.20.1.150;branch=z9hG4bK7aecb482
Call-ID: [email protected]:5060
From: “+18683366028” sip:[email protected];tag=as1d22969b
To: sip:[email protected];tag=87d0ec37-92d7-4318-bff5-cfacb2912ff9
CSeq: 102 CANCEL
Server: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Transmitting SIP response (507 bytes) to UDP:172.20.1.150:5060 —>
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 172.20.1.150:5060;rport=5060;received=172.20.1.150;branch=z9hG4bK7aecb482
Call-ID: [email protected]:5060
From: “+18683366028” sip:[email protected];tag=as1d22969b
To: sip:[email protected];tag=87d0ec37-92d7-4318-bff5-cfacb2912ff9
CSeq: 102 INVITE
Server: FPBX-13.0.190.19(13.12.1)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Content-Length: 0

== Spawn extension (macro-dial, s, 19) exited non-zero on ‘PJSIP/4824775-0000005b’ in macro ‘dial’
== Spawn extension (followme-sub, 2150, 37) exited non-zero on ‘PJSIP/4824775-0000005b’
<— Transmitting SIP request (421 bytes) to UDP:172.20.1.10:5060 —>
CANCEL sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPjf7304293-b740-4dfd-8d3b-c9f48e6bc1b6
From: “+18683366028” sip:[email protected];tag=6d1e4b20-f3be-4a00-9a4a-258beece7af4
To: sip:[email protected]
Call-ID: dd9ab08e-9060-4c05-b9f7-8e09b2798595
CSeq: 1667 CANCEL
Reason: Q.850;cause=0
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP request (431 bytes) from UDP:172.20.1.150:5060 —>
ACK sip:172.20.1.20:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.150:5060;branch=z9hG4bK7aecb482;rport
Max-Forwards: 70
From: “+18683366028” sip:[email protected];tag=as1d22969b
To: sip:[email protected];tag=87d0ec37-92d7-4318-bff5-cfacb2912ff9
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 ACK
User-Agent: VoxStack Wireless Gateway
Content-Length: 0

<— Received SIP response (378 bytes) from UDP:172.20.1.10:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPjf7304293-b740-4dfd-8d3b-c9f48e6bc1b6
From: “+18683366028” sip:[email protected];tag=6d1e4b20-f3be-4a00-9a4a-258beece7af4
To: sip:[email protected];tag=2872468517
Call-ID: dd9ab08e-9060-4c05-b9f7-8e09b2798595
CSeq: 1667 CANCEL
User-Agent: Yealink SIP-T21P_E2 52.81.0.60
Content-Length: 0

<— Received SIP response (393 bytes) from UDP:172.20.1.10:5060 —>
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPjf7304293-b740-4dfd-8d3b-c9f48e6bc1b6
From: “+18683366028” sip:[email protected];tag=6d1e4b20-f3be-4a00-9a4a-258beece7af4
To: sip:[email protected];tag=2872468517
Call-ID: dd9ab08e-9060-4c05-b9f7-8e09b2798595
CSeq: 1667 INVITE
User-Agent: Yealink SIP-T21P_E2 52.81.0.60
Content-Length: 0

<— Transmitting SIP request (407 bytes) to UDP:172.20.1.10:5060 —>
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPjf7304293-b740-4dfd-8d3b-c9f48e6bc1b6
From: “+18683366028” sip:[email protected];tag=6d1e4b20-f3be-4a00-9a4a-258beece7af4
To: sip:[email protected];tag=2872468517
Call-ID: dd9ab08e-9060-4c05-b9f7-8e09b2798595
CSeq: 1667 ACK
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Transmitting SIP request (435 bytes) to UDP:172.20.1.150:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPjcaff6092-1cb4-489c-9bae-900bb3e23d21
From: sip:[email protected];tag=f2dd8d73-cab8-4840-830c-7211bf96cb2e
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: aa71837a-a70a-4ecc-8ab9-7baac37774b9
CSeq: 50560 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (551 bytes) from UDP:172.20.1.150:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;branch=z9hG4bKPjcaff6092-1cb4-489c-9bae-900bb3e23d21;received=172.20.1.20;rport=5060
From: sip:[email protected];tag=f2dd8d73-cab8-4840-830c-7211bf96cb2e
To: sip:[email protected];tag=as2a2419a7
Call-ID: aa71837a-a70a-4ecc-8ab9-7baac37774b9
CSeq: 50560 OPTIONS
Server: VoxStack Wireless Gateway
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:172.20.1.150:5060
Accept: application/sdp
Content-Length: 0

<— Transmitting SIP request (435 bytes) to UDP:172.20.1.150:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPj6d5f4a69-b56c-4932-b7bd-aa38ff0b63c2
From: sip:[email protected];tag=77024923-9592-4c87-b644-7faf1fabf851
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: 697bfcf4-56fd-41a3-8ef6-043c32142061
CSeq: 28235 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (551 bytes) from UDP:172.20.1.150:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;branch=z9hG4bKPj6d5f4a69-b56c-4932-b7bd-aa38ff0b63c2;received=172.20.1.20;rport=5060
From: sip:[email protected];tag=77024923-9592-4c87-b644-7faf1fabf851
To: sip:[email protected];tag=as39ba4849
Call-ID: 697bfcf4-56fd-41a3-8ef6-043c32142061
CSeq: 28235 OPTIONS
Server: VoxStack Wireless Gateway
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:172.20.1.150:5060
Accept: application/sdp
Content-Length: 0

<— Transmitting SIP request (421 bytes) to UDP:172.20.1.10:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPjea956917-970c-4227-bb7a-61bd95afddfa
From: sip:[email protected];tag=258224c3-c619-4556-b845-84b7f69c1292
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: 7b77cea4-dfec-4060-ac50-aa81d4c8cf27
CSeq: 43460 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (362 bytes) from UDP:172.20.1.10:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPjea956917-970c-4227-bb7a-61bd95afddfa
From: sip:[email protected];tag=258224c3-c619-4556-b845-84b7f69c1292
To: sip:[email protected];tag=2829455130
Call-ID: 7b77cea4-dfec-4060-ac50-aa81d4c8cf27
CSeq: 43460 OPTIONS
User-Agent: Yealink SIP-T21P_E2 52.81.0.60
Content-Length: 0

<— Transmitting SIP request (421 bytes) to UDP:172.20.1.10:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPj070323cb-55c7-4e6c-983e-8c7c0100c5c2
From: sip:[email protected];tag=f902908d-33a9-439b-9d5f-0f042c9ee667
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: 34115def-11a2-4af8-88cc-bd7de291ff5b
CSeq: 10308 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (361 bytes) from UDP:172.20.1.10:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPj070323cb-55c7-4e6c-983e-8c7c0100c5c2
From: sip:[email protected];tag=f902908d-33a9-439b-9d5f-0f042c9ee667
To: sip:[email protected];tag=363970636
Call-ID: 34115def-11a2-4af8-88cc-bd7de291ff5b
CSeq: 10308 OPTIONS
User-Agent: Yealink SIP-T21P_E2 52.81.0.60
Content-Length: 0

localhostCLI> core set verbose 0
Console verbose was 4 and is now OFF.
localhostCLI> pjsip set logger off
PJSIP Logging disabled
localhost*CLI>

I saw the call ran up the screen but I didn’t see it show up in the log I copied. I used putty then copy all to clipboard. I sure feel I miss what you were looking for in the capture.

danielf · April 26, 2017, 2:18pm

Hello @renrick,

Your To field is empty and because of that the Asterisk does not know what to do with it and terminate the call.

I would have tried configure a SIP trunk towards the GSM gateway (do not delete the existing PJSIP trunk) and retest again. Keep in mind that the port of the SIP is different from the default (5060). You can verify that with this command: netstat -anop | grep asterisk.

Thank you,

Daniel Friedman
Trixton LTD.

renrick · April 26, 2017, 2:54pm

Hi @danielf,

I created new sip trunk 1005 with steering digit for outbound route of 55. I placed a test call to my pbx and the call was received on my cell phone.

Not sure if this still makes sense. Here is the pjsip output.

– Channel PJSIP/4824775-00000065 left ‘simple_bridge’ basic-bridge <53459037-b6d5-459a-8a8b-f79abb9dff7f>
== Spawn extension (macro-dial, s, 19) exited non-zero on ‘PJSIP/4824775-00000065’ in macro ‘dial’
== Spawn extension (followme-sub, 2150, 37) exited non-zero on ‘PJSIP/4824775-00000065’
– Channel Local/554992727@from-internal-00000014;1 left ‘simple_bridge’ basic-bridge <53459037-b6d5-459a-8a8b-f79abb9dff7f>
– Channel Local/554992727@from-internal-00000014;2 left ‘simple_bridge’ basic-bridge <10ea4f5d-f53b-4561-b05f-289d599580c3>
== Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on ‘Local/554992727@from-internal-00000014;2’ in macro ‘dialout-trunk’
== Spawn extension (from-internal, 554992727, 6) exited non-zero on ‘Local/554992727@from-internal-00000014;2’
– Executing [h@from-internal:1] Macro(“Local/554992727@from-internal-00000014;2”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“Local/554992727@from-internal-00000014;2”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Channel SIP/1005-00000001 left ‘simple_bridge’ basic-bridge <10ea4f5d-f53b-4561-b05f-289d599580c3>
– Executing [s@macro-hangupcall:3] ExecIf(“Local/554992727@from-internal-00000014;2”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall:4] Hangup(“Local/554992727@from-internal-00000014;2”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘Local/554992727@from-internal-00000014;2’ in macro ‘hangupcall’
== Spawn extension (from-internal, h, 1) exited non-zero on ‘Local/554992727@from-internal-00000014;2’
<— Received SIP request (535 bytes) from UDP:172.20.1.11:5160 —>
OPTIONS sip:172.20.1.20 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.11:5160;branch=z9hG4bK228096421;rport
Route: sip:172.20.1.20:5060;lr
From: sip:[email protected];tag=1942743425
To: sip:172.20.1.20
Call-ID: [email protected]
CSeq: 252960 OPTIONS
Contact: sip:[email protected]:5160
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP1630 1.0.4.22
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0

<— Transmitting SIP response (476 bytes) to UDP:172.20.1.11:5160 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.20.1.11:5160;rport=5160;received=172.20.1.11;branch=z9hG4bK228096421
Call-ID: [email protected]
From: sip:[email protected];tag=1942743425
To: sip:172.20.1.20;tag=z9hG4bK228096421
CSeq: 252960 OPTIONS
WWW-Authenticate: Digest realm=“asterisk”,nonce=“1493218233/cf77ffcb743f4666f503fbe8ac9dc750”,opaque=“35a51e1b53f467a2”,algorithm=md5,qop="auth"
Server: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP request (797 bytes) from UDP:172.20.1.11:5160 —>
OPTIONS sip:172.20.1.20 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.11:5160;branch=z9hG4bK528918796;rport
Route: sip:172.20.1.20:5060;lr
From: sip:[email protected];tag=1942743425
To: sip:172.20.1.20
Call-ID: [email protected]
CSeq: 252961 OPTIONS
Contact: sip:[email protected]:5160
Authorization: Digest username=“4814”, realm=“asterisk”, nonce=“1493218233/cf77ffcb743f4666f503fbe8ac9dc750”, uri=“sip:172.20.1.20”, response=“6f1a6a9dbc565ff86933134199ae6bb5”, algorithm=md5, cnonce=“08827039”, opaque=“35a51e1b53f467a2”, qop=auth, nc=0000005a
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP1630 1.0.4.22
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0

<— Transmitting SIP response (806 bytes) to UDP:172.20.1.11:5160 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.11:5160;rport=5160;received=172.20.1.11;branch=z9hG4bK528918796
Call-ID: [email protected]
From: sip:[email protected];tag=1942743425
To: sip:172.20.1.20;tag=z9hG4bK528918796
CSeq: 252961 OPTIONS
Accept: application/sdp, application/dialog-info+xml, application/simple-message-summary, application/pidf+xml, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Accept-Encoding: text/plain
Accept-Language: en
Server: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Transmitting SIP request (421 bytes) to UDP:172.20.1.11:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPjadc6cb2b-867d-40eb-b0ba-16c4dc878fe0
From: sip:[email protected];tag=df173f81-3c1c-4ba1-9abb-9420b4eaf6b5
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: a463007c-643c-41e1-9d9e-a83d7d9014ec
CSeq: 65520 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (485 bytes) from UDP:172.20.1.11:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPjadc6cb2b-867d-40eb-b0ba-16c4dc878fe0
From: sip:[email protected];tag=df173f81-3c1c-4ba1-9abb-9420b4eaf6b5
To: sip:[email protected];tag=1950689433
Call-ID: a463007c-643c-41e1-9d9e-a83d7d9014ec
CSeq: 65520 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GXP1630 1.0.4.22
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0

<— Transmitting SIP request (421 bytes) to UDP:172.20.1.10:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPjc45d2f09-fb77-4d8c-b157-4ba29cbad874
From: sip:[email protected];tag=fadfc4d9-18cb-4415-a214-b4fe5bbcb0d7
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: a169dcb4-bb78-4933-876b-f2307725dc1a
CSeq: 61781 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (362 bytes) from UDP:172.20.1.10:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPjc45d2f09-fb77-4d8c-b157-4ba29cbad874
From: sip:[email protected];tag=fadfc4d9-18cb-4415-a214-b4fe5bbcb0d7
To: sip:[email protected];tag=4141680073
Call-ID: a169dcb4-bb78-4933-876b-f2307725dc1a
CSeq: 61781 OPTIONS
User-Agent: Yealink SIP-T21P_E2 52.81.0.60
Content-Length: 0

<— Transmitting SIP request (421 bytes) to UDP:172.20.1.10:5060 —>
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPja3ae7be6-d0df-4d87-bb4a-7b47896a1231
From: sip:[email protected];tag=ff8662a0-e064-4633-97e1-e86706799a41
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: 4bc074a0-b656-4cdd-b8f4-f685fa85c213
CSeq: 48774 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (362 bytes) from UDP:172.20.1.10:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport=5060;branch=z9hG4bKPja3ae7be6-d0df-4d87-bb4a-7b47896a1231
From: sip:[email protected];tag=ff8662a0-e064-4633-97e1-e86706799a41
To: sip:[email protected];tag=2731740144
Call-ID: 4bc074a0-b656-4cdd-b8f4-f685fa85c213
CSeq: 48774 OPTIONS
User-Agent: Yealink SIP-T21P_E2 52.81.0.60
Content-Length: 0

localhost*CLI> core set vebose off
No such command ‘core set vebose off’ (type ‘core show help core set vebose off’ for other possible commands)
<— Transmitting SIP request (411 bytes) to UDP:172.20.1.13:5060 —>
OPTIONS sip:172.20.1.13:5060 SIP/2.0
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPj7ed755eb-0d15-462a-aa2f-f71de586d5e8
From: sip:[email protected];tag=b067d430-aefd-48fe-a595-cd43266c1fde
To: sip:172.20.1.13
Contact: sip:[email protected]:5060
Call-ID: 5ae36293-5745-4b38-8832-a42ccb37fc0b
CSeq: 48445 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-13.0.190.19(13.12.1)
Content-Length: 0

<— Received SIP response (550 bytes) from UDP:172.20.1.13:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.20.1.20:5060;rport;branch=z9hG4bKPj7ed755eb-0d15-462a-aa2f-f71de586d5e8
From: sip:[email protected];tag=b067d430-aefd-48fe-a595-cd43266c1fde
To: sip:172.20.1.13;tag=z9hG4bKe67217b773f52d47
Call-ID: 5ae36293-5745-4b38-8832-a42ccb37fc0b
CSeq: 48445 OPTIONS
User-Agent: Grandstream GXW4104 (HW 2.3, Ch:8) 1.4.1.5
Contact: sip:[email protected]:5060;transport=udp
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK
Supported: replaces, timer, 100rel, path
Content-Length: 0

localhostCLI> core set verbose off
Console verbose was 4 and is now OFF.
localhostCLI> pjsip set logger off
PJSIP Logging disabled
localhost*CLI>

danielf · April 26, 2017, 3:00pm

Hello @renrick,

I did not understand, Is it working now as expected or not? for sip debugging you can use this command:
sip set debug on and to turn it off sip set debug off.

Thank you,

Daniel Friedman
Trixton LTD.

renrick · April 27, 2017, 1:04am

Hello @danielf,

Sorry for the mix up. I created a sip trunk as you suggested and the sip trunk worked. I still posted the pjsip output from that call as one portion of that call was pjsip. IE the call came in on a pjsip trunk and went out via follow me on the new sip trunk I created. While this created a work around I am still unsure as to why it didn’t work with the pjsip trunk or how to make it work using the pjsip trunk. I can use this but I usually like to know how to solve a problem if it’s solvable. Thank you for your input and valuable time.

danielf · April 27, 2017, 5:41am

Hello @renrick,

Good to hear that it is working now.

There is no problem to work with both of the sip channels (chan_sip and chan_pjsip). The problem of pjsip is that it is not suitable for older equipment.
In general, If you want to make your life easier with your providers or gateways keep using the chan_sip as before.

Thank you,

Daniel Friedman
Trixton LTD.

renrick · April 27, 2017, 5:46am

Thanks for your assistance @danielf. Much appreciated. One thing I notice though, I tried setting the port to 5160 but the trunk became unreachable. I didn’t specify a port number and it defaulted to 5060. I did check the advance settings and realized that sip used 5160 and pjsip used 5060. Care to shed any light on that? Why it didn’t work with 5160 for the older sip but instead work with 5060?