FreePBX receives 486 Busy from endpoints but then sends to our provider as 503 Service Unavailable

a0429 · February 9, 2021, 6:00pm

Hi,

We have a big problem where our PBX receives a 486 busy message from our SBC, but then forwards this on as 503 Service unavailable. Because the PBX sends 503 service unavailable our provider repeatedly tries to setup the call. Can someone help identify wht the 486 is fowarded to our provider as 503?

Endpoints sends 486 Busy message

PBX sends provider 503 even though it is 486 that was received from the endpoint

Thanks in advance

billsimon · February 9, 2021, 6:05pm

Are you using PJSIP or chan_sip for these connections?

a0429 · February 9, 2021, 7:59pm

PJSIP - the SIP trunk is between the SIP provider --> PBX --> SBC are all PJSIP.

The SBC sends the PBX the 486 busy message, which then the PBX sends our SIP provider 503 Service Unavailable messages.

Becayse our provider retries on Service Unavailable after a set time, it is causing a huge influx of calls…

a0429 · February 9, 2021, 8:00pm

As above. No idea why but in my experience the PBX should just send through the 486 Busy message

a0429 · February 9, 2021, 8:21pm

I have done more tests. When I set the DDI destination to an extension, dial it and stay in the call and then place another call, the device sends 486 to the pbx which sends the 486 message to our provider, so the mobile that placed the call receives User Busy.

Its only when our SBC sends the 486 message on busy, that the PBX sends 503 unavailable here.

billsimon · February 9, 2021, 8:30pm

Verbose logs from the timeframe of a call may help, as well as a full SIP trace (not just the ladder diagram).

a0429 · February 9, 2021, 8:52pm

First Call:

[2021-02-09 21:41:01] VERBOSE[85008] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘192.168.222.3’
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:1] Set(“PJSIP/to_sipprovider_primary-00001685”, “__DIRECTION=INBOUND”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:2] Gosub(“PJSIP/to_sipprovider_primary-00001685”, “sub-record-check,s,1(in,+499119380003,dontcare)”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “0?initialized”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/to_sipprovider_primary-00001685”, “__REC_STATUS=INITIALIZED”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIP/to_sipprovider_primary-00001685”, “NOW=1612903261”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/to_sipprovider_primary-00001685”, “__DAY=09”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/to_sipprovider_primary-00001685”, “__MONTH=02”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/to_sipprovider_primary-00001685”, “__YEAR=2021”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/to_sipprovider_primary-00001685”, “__TIMESTR=20210209-214101”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/to_sipprovider_primary-00001685”, “__FROMEXTEN=unknown”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/to_sipprovider_primary-00001685”, “__MON_FMT=wav”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/to_sipprovider_primary-00001685”, “Recordings initialized”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “0?Set(ARG3=dontcare)”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/to_sipprovider_primary-00001685”, “REC_POLICY_MODE_SAVE=”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “0?Set(REC_STATUS=NO)”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “2?checkaction”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (sub-record-check,s,17)
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “1?sub-record-check,in,1”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (sub-record-check,in,1)
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [in@sub-record-check:1] NoOp(“PJSIP/to_sipprovider_primary-00001685”, “Inbound Recording Check to +499119380003”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [in@sub-record-check:2] Set(“PJSIP/to_sipprovider_primary-00001685”, “FROMEXTEN=unknown”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [in@sub-record-check:3] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “14?Set(FROMEXTEN=00447834987586)”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [in@sub-record-check:4] Gosub(“PJSIP/to_sipprovider_primary-00001685”, “recordcheck,1(dontcare,in,+499119380003)”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/to_sipprovider_primary-00001685”, “Starting recording check against dontcare”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/to_sipprovider_primary-00001685”, “dontcare”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/to_sipprovider_primary-00001685”, “”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [in@sub-record-check:5] Return(“PJSIP/to_sipprovider_primary-00001685”, “”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:3] Set(“PJSIP/to_sipprovider_primary-00001685”, “CHANNEL(tonezone)=us”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:4] Set(“PJSIP/to_sipprovider_primary-00001685”, “__FROM_DID=+499119380003”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:5] Set(“PJSIP/to_sipprovider_primary-00001685”, “returnhere=1”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:6] Gosub(“PJSIP/to_sipprovider_primary-00001685”, “app-blacklist-check,s,1()”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “0?blacklisted”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@app-blacklist-check:2] Set(“PJSIP/to_sipprovider_primary-00001685”, “CALLED_BLACKLIST=1”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [s@app-blacklist-check:3] Return(“PJSIP/to_sipprovider_primary-00001685”, “”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:7] Set(“PJSIP/to_sipprovider_primary-00001685”, “CDR(did)=+499119380003”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:8] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “0?”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:9] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “0 ?Set(CALLERID(name)=00447834987586)”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:10] Set(“PJSIP/to_sipprovider_primary-00001685”, “__MOHCLASS=”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:11] Set(“PJSIP/to_sipprovider_primary-00001685”, “__REVERSAL_REJECT=FALSE”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:12] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “1?post-reverse-charge”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (from-pstn,+499119380003,14)
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:14] NoOp(“PJSIP/to_sipprovider_primary-00001685”, “”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:15] Set(“PJSIP/to_sipprovider_primary-00001685”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:16] Set(“PJSIP/to_sipprovider_primary-00001685”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:17] Set(“PJSIP/to_sipprovider_primary-00001685”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:18] Set(“PJSIP/to_sipprovider_primary-00001685”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:19] NoOp(“PJSIP/to_sipprovider_primary-00001685”, “CallerID Entry Point”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:20] Set(“PJSIP/to_sipprovider_primary-00001685”, “__CRM_DIRECTION=INBOUND”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:21] Set(“PJSIP/to_sipprovider_primary-00001685”, “__CRM_SOURCE=00447834987586”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:22] Set(“PJSIP/to_sipprovider_primary-00001685”, “__CRM_LINKEDID=1612903261.12056”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:23] AGI(“PJSIP/to_sipprovider_primary-00001685”, “sangomacrm.agi,true”) in new stack
[2021-02-09 21:41:01] VERBOSE[57351][C-00000b3a] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] res_agi.c: <PJSIP/to_sipprovider_primary-00001685>AGI Script sangomacrm.agi completed, returning 0
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:24] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [+499119380003@from-pstn:25] Goto(“PJSIP/to_sipprovider_primary-00001685”, “ext-trunk,2,1”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (ext-trunk,2,1)
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [2@ext-trunk:1] Set(“PJSIP/to_sipprovider_primary-00001685”, “TDIAL_SUFFIX=@sbctrunk”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [2@ext-trunk:2] Set(“PJSIP/to_sipprovider_primary-00001685”, “TDIAL_STRING=PJSIP”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [2@ext-trunk:3] Set(“PJSIP/to_sipprovider_primary-00001685”, “DIAL_TRUNK=2”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [2@ext-trunk:4] Goto(“PJSIP/to_sipprovider_primary-00001685”, “ext-trunk,tdial,1”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (ext-trunk,tdial,1)
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:1] Set(“PJSIP/to_sipprovider_primary-00001685”, “OUTBOUND_GROUP=OUT_2”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:2] GotoIf(“PJSIP/to_sipprovider_primary-00001685”, “1?nomax”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx_builtins.c: Goto (ext-trunk,tdial,4)
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:4] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “1?Set(CALLERPRES(name-pres)=allowed_not_screened)”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:5] ExecIf(“PJSIP/to_sipprovider_primary-00001685”, “1?Set(CALLERPRES(num-pres)=allowed_not_screened)”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:6] Set(“PJSIP/to_sipprovider_primary-00001685”, “DIAL_NUMBER=+499119380003”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:7] GosubIf(“PJSIP/to_sipprovider_primary-00001685”, “0?sub-flp-2,s,1()”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:8] Set(“PJSIP/to_sipprovider_primary-00001685”, “OUTNUM=+499119380003”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:9] Set(“PJSIP/to_sipprovider_primary-00001685”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] pbx.c: Executing [tdial@ext-trunk:10] Dial(“PJSIP/to_sipprovider_primary-00001685”, “PJSIP/+499119380003@sbctrunk,300,T”) in new stack
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] app_dial.c: Called PJSIP/+499119380003@sbctrunk
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:02] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is making progress passing it to PJSIP/to_sipprovider_primary-00001685
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is making progress passing it to PJSIP/to_sipprovider_primary-00001685
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:03] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 is ringing
[2021-02-09 21:41:06] VERBOSE[57351][C-00000b3a] app_dial.c: PJSIP/sbctrunk-00001686 answered PJSIP/to_sipprovider_primary-00001685
[2021-02-09 21:41:06] VERBOSE[57395][C-00000b3a] bridge_channel.c: Channel PJSIP/sbctrunk-00001686 joined ‘simple_bridge’ basic-bridge
[2021-02-09 21:41:06] VERBOSE[57351][C-00000b3a] bridge_channel.c: Channel PJSIP/to_sipprovider_primary-00001685 joined ‘simple_bridge’ basic-bridge

a0429 · February 9, 2021, 8:52pm

Whilst in first call (so should return busy)

[2021-02-09 21:41:47] VERBOSE[54947] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘192.168.222.3’
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:1] Set(“PJSIP/to_telefonica_primary-00001687”, “__DIRECTION=INBOUND”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:2] Gosub(“PJSIP/to_telefonica_primary-00001687”, “sub-record-check,s,1(in,+499119380003,dontcare)”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “0?initialized”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/to_telefonica_primary-00001687”, “__REC_STATUS=INITIALIZED”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIP/to_telefonica_primary-00001687”, “NOW=1612903307”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/to_telefonica_primary-00001687”, “__DAY=09”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/to_telefonica_primary-00001687”, “__MONTH=02”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/to_telefonica_primary-00001687”, “__YEAR=2021”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/to_telefonica_primary-00001687”, “__TIMESTR=20210209-214147”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/to_telefonica_primary-00001687”, “__FROMEXTEN=unknown”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/to_telefonica_primary-00001687”, “__MON_FMT=wav”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/to_telefonica_primary-00001687”, “Recordings initialized”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “0?Set(ARG3=dontcare)”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/to_telefonica_primary-00001687”, “REC_POLICY_MODE_SAVE=”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “0?Set(REC_STATUS=NO)”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “2?checkaction”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (sub-record-check,s,17)
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “1?sub-record-check,in,1”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (sub-record-check,in,1)
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [in@sub-record-check:1] NoOp(“PJSIP/to_telefonica_primary-00001687”, “Inbound Recording Check to +499119380003”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [in@sub-record-check:2] Set(“PJSIP/to_telefonica_primary-00001687”, “FROMEXTEN=unknown”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [in@sub-record-check:3] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “14?Set(FROMEXTEN=00447969776426)”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [in@sub-record-check:4] Gosub(“PJSIP/to_telefonica_primary-00001687”, “recordcheck,1(dontcare,in,+499119380003)”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/to_telefonica_primary-00001687”, “Starting recording check against dontcare”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/to_telefonica_primary-00001687”, “dontcare”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/to_telefonica_primary-00001687”, “”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [in@sub-record-check:5] Return(“PJSIP/to_telefonica_primary-00001687”, “”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:3] Set(“PJSIP/to_telefonica_primary-00001687”, “CHANNEL(tonezone)=us”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:4] Set(“PJSIP/to_telefonica_primary-00001687”, “__FROM_DID=+499119380003”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:5] Set(“PJSIP/to_telefonica_primary-00001687”, “returnhere=1”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:6] Gosub(“PJSIP/to_telefonica_primary-00001687”, “app-blacklist-check,s,1()”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “0?blacklisted”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@app-blacklist-check:2] Set(“PJSIP/to_telefonica_primary-00001687”, “CALLED_BLACKLIST=1”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@app-blacklist-check:3] Return(“PJSIP/to_telefonica_primary-00001687”, “”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:7] Set(“PJSIP/to_telefonica_primary-00001687”, “CDR(did)=+499119380003”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:8] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “0?”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:9] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “0 ?Set(CALLERID(name)=00447969776426)”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:10] Set(“PJSIP/to_telefonica_primary-00001687”, “__MOHCLASS=”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:11] Set(“PJSIP/to_telefonica_primary-00001687”, “__REVERSAL_REJECT=FALSE”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:12] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “1?post-reverse-charge”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (from-pstn,+499119380003,14)
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:14] NoOp(“PJSIP/to_telefonica_primary-00001687”, “”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:15] Set(“PJSIP/to_telefonica_primary-00001687”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:16] Set(“PJSIP/to_telefonica_primary-00001687”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:17] Set(“PJSIP/to_telefonica_primary-00001687”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:18] Set(“PJSIP/to_telefonica_primary-00001687”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:19] NoOp(“PJSIP/to_telefonica_primary-00001687”, “CallerID Entry Point”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:20] Set(“PJSIP/to_telefonica_primary-00001687”, “__CRM_DIRECTION=INBOUND”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:21] Set(“PJSIP/to_telefonica_primary-00001687”, “__CRM_SOURCE=00447969776426”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:22] Set(“PJSIP/to_telefonica_primary-00001687”, “__CRM_LINKEDID=1612903307.12058”) in new stack
[2021-02-09 21:41:47] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:23] AGI(“PJSIP/to_telefonica_primary-00001687”, “sangomacrm.agi,true”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] res_agi.c: <PJSIP/to_telefonica_primary-00001687>AGI Script sangomacrm.agi completed, returning 0
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:24] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [+499119380003@from-pstn:25] Goto(“PJSIP/to_telefonica_primary-00001687”, “ext-trunk,2,1”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (ext-trunk,2,1)
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [2@ext-trunk:1] Set(“PJSIP/to_telefonica_primary-00001687”, “TDIAL_SUFFIX=@fronerisbc”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [2@ext-trunk:2] Set(“PJSIP/to_telefonica_primary-00001687”, “TDIAL_STRING=PJSIP”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [2@ext-trunk:3] Set(“PJSIP/to_telefonica_primary-00001687”, “DIAL_TRUNK=2”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [2@ext-trunk:4] Goto(“PJSIP/to_telefonica_primary-00001687”, “ext-trunk,tdial,1”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (ext-trunk,tdial,1)
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:1] Set(“PJSIP/to_telefonica_primary-00001687”, “OUTBOUND_GROUP=OUT_2”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:2] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “1?nomax”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx_builtins.c: Goto (ext-trunk,tdial,4)
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:4] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “1?Set(CALLERPRES(name-pres)=allowed_not_screened)”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:5] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “1?Set(CALLERPRES(num-pres)=allowed_not_screened)”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:6] Set(“PJSIP/to_telefonica_primary-00001687”, “DIAL_NUMBER=+499119380003”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:7] GosubIf(“PJSIP/to_telefonica_primary-00001687”, “0?sub-flp-2,s,1()”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:8] Set(“PJSIP/to_telefonica_primary-00001687”, “OUTNUM=+499119380003”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:9] Set(“PJSIP/to_telefonica_primary-00001687”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:10] Dial(“PJSIP/to_telefonica_primary-00001687”, “PJSIP/+499119380003@fronerisbc,300,T”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: Called PJSIP/+499119380003@fronerisbc
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: PJSIP/fronerisbc-00001688 is ringing
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: PJSIP/fronerisbc-00001688 is ringing
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: Everyone is busy/congested at this time (1:0/1/0)
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:11] Set(“PJSIP/to_telefonica_primary-00001687”, “CALLERID(number)=00447969776426”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:12] Set(“PJSIP/to_telefonica_primary-00001687”, “CALLERID(name)=+447969776426”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [tdial@ext-trunk:13] Hangup(“PJSIP/to_telefonica_primary-00001687”, “”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Spawn extension (ext-trunk, tdial, 13) exited non-zero on ‘PJSIP/to_telefonica_primary-00001687’
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_stack.c: PJSIP/to_telefonica_primary-00001687 Internal Gosub(crm-hangup,s,1) start
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:1] NoOp(“PJSIP/to_telefonica_primary-00001687”, “Sending Hangup to CRM”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:2] NoOp(“PJSIP/to_telefonica_primary-00001687”, “HANGUP CAUSE: 34”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:3] ExecIf(“PJSIP/to_telefonica_primary-00001687”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:4] NoOp(“PJSIP/to_telefonica_primary-00001687”, “MASTER CHANNEL: 1612903307.12058 = 1612903307.12058”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:5] GotoIf(“PJSIP/to_telefonica_primary-00001687”, “0?return”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:6] Set(“PJSIP/to_telefonica_primary-00001687”, “__CRM_HANGUP=1”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:7] AGI(“PJSIP/to_telefonica_primary-00001687”, “sangomacrm.agi”) in new stack
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2021-02-09 21:41:49] VERBOSE[57589][C-00000b3b] res_agi.c: <PJSIP/to_telefonica_primary-00001687>AGI Script sangomacrm.agi completed, returning 0
[2021-02-09 21:41:49] VERBOSE[57589][C-00000b3b] pbx.c: Executing [s@crm-hangup:8] Return(“PJSIP/to_telefonica_primary-00001687”, “”) in new stack
[2021-02-09 21:41:49] VERBOSE[57589][C-00000b3b] app_stack.c: Spawn extension (ext-trunk, tdial, 13) exited non-zero on ‘PJSIP/to_telefonica_primary-00001687’
[2021-02-09 21:41:49] VERBOSE[57589][C-00000b3b] app_stack.c: PJSIP/to_telefonica_primary-00001687 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2021-02-09 21:41:49] VERBOSE[54947] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘192.168.222.3’
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:1] Set(“PJSIP/to_telefonica_primary-00001689”, “__DIRECTION=INBOUND”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:2] Gosub(“PJSIP/to_telefonica_primary-00001689”, “sub-record-check,s,1(in,+499119380003,dontcare)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “0?initialized”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/to_telefonica_primary-00001689”, “__REC_STATUS=INITIALIZED”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIP/to_telefonica_primary-00001689”, “NOW=1612903309”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/to_telefonica_primary-00001689”, “__DAY=09”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/to_telefonica_primary-00001689”, “__MONTH=02”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/to_telefonica_primary-00001689”, “__YEAR=2021”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/to_telefonica_primary-00001689”, “__TIMESTR=20210209-214149”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/to_telefonica_primary-00001689”, “__FROMEXTEN=unknown”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/to_telefonica_primary-00001689”, “__MON_FMT=wav”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/to_telefonica_primary-00001689”, “Recordings initialized”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “0?Set(ARG3=dontcare)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/to_telefonica_primary-00001689”, “REC_POLICY_MODE_SAVE=”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “0?Set(REC_STATUS=NO)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “2?checkaction”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (sub-record-check,s,17)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “1?sub-record-check,in,1”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (sub-record-check,in,1)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [in@sub-record-check:1] NoOp(“PJSIP/to_telefonica_primary-00001689”, “Inbound Recording Check to +499119380003”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [in@sub-record-check:2] Set(“PJSIP/to_telefonica_primary-00001689”, “FROMEXTEN=unknown”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [in@sub-record-check:3] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “14?Set(FROMEXTEN=00447969776426)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [in@sub-record-check:4] Gosub(“PJSIP/to_telefonica_primary-00001689”, “recordcheck,1(dontcare,in,+499119380003)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/to_telefonica_primary-00001689”, “Starting recording check against dontcare”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/to_telefonica_primary-00001689”, “dontcare”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/to_telefonica_primary-00001689”, “”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [in@sub-record-check:5] Return(“PJSIP/to_telefonica_primary-00001689”, “”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:3] Set(“PJSIP/to_telefonica_primary-00001689”, “CHANNEL(tonezone)=us”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:4] Set(“PJSIP/to_telefonica_primary-00001689”, “__FROM_DID=+499119380003”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:5] Set(“PJSIP/to_telefonica_primary-00001689”, “returnhere=1”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:6] Gosub(“PJSIP/to_telefonica_primary-00001689”, “app-blacklist-check,s,1()”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “0?blacklisted”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@app-blacklist-check:2] Set(“PJSIP/to_telefonica_primary-00001689”, “CALLED_BLACKLIST=1”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@app-blacklist-check:3] Return(“PJSIP/to_telefonica_primary-00001689”, “”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:7] Set(“PJSIP/to_telefonica_primary-00001689”, “CDR(did)=+499119380003”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:8] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “0?”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:9] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “0 ?Set(CALLERID(name)=00447969776426)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:10] Set(“PJSIP/to_telefonica_primary-00001689”, “__MOHCLASS=”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:11] Set(“PJSIP/to_telefonica_primary-00001689”, “__REVERSAL_REJECT=FALSE”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:12] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “1?post-reverse-charge”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (from-pstn,+499119380003,14)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:14] NoOp(“PJSIP/to_telefonica_primary-00001689”, “”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:15] Set(“PJSIP/to_telefonica_primary-00001689”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:16] Set(“PJSIP/to_telefonica_primary-00001689”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:17] Set(“PJSIP/to_telefonica_primary-00001689”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:18] Set(“PJSIP/to_telefonica_primary-00001689”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:19] NoOp(“PJSIP/to_telefonica_primary-00001689”, “CallerID Entry Point”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:20] Set(“PJSIP/to_telefonica_primary-00001689”, “__CRM_DIRECTION=INBOUND”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:21] Set(“PJSIP/to_telefonica_primary-00001689”, “__CRM_SOURCE=00447969776426”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:22] Set(“PJSIP/to_telefonica_primary-00001689”, “__CRM_LINKEDID=1612903309.12060”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:23] AGI(“PJSIP/to_telefonica_primary-00001689”, “sangomacrm.agi,true”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] res_agi.c: <PJSIP/to_telefonica_primary-00001689>AGI Script sangomacrm.agi completed, returning 0
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:24] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [+499119380003@from-pstn:25] Goto(“PJSIP/to_telefonica_primary-00001689”, “ext-trunk,2,1”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (ext-trunk,2,1)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [2@ext-trunk:1] Set(“PJSIP/to_telefonica_primary-00001689”, “TDIAL_SUFFIX=@fronerisbc”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [2@ext-trunk:2] Set(“PJSIP/to_telefonica_primary-00001689”, “TDIAL_STRING=PJSIP”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [2@ext-trunk:3] Set(“PJSIP/to_telefonica_primary-00001689”, “DIAL_TRUNK=2”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [2@ext-trunk:4] Goto(“PJSIP/to_telefonica_primary-00001689”, “ext-trunk,tdial,1”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (ext-trunk,tdial,1)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:1] Set(“PJSIP/to_telefonica_primary-00001689”, “OUTBOUND_GROUP=OUT_2”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:2] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “1?nomax”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx_builtins.c: Goto (ext-trunk,tdial,4)
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:4] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “1?Set(CALLERPRES(name-pres)=allowed_not_screened)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:5] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “1?Set(CALLERPRES(num-pres)=allowed_not_screened)”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:6] Set(“PJSIP/to_telefonica_primary-00001689”, “DIAL_NUMBER=+499119380003”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:7] GosubIf(“PJSIP/to_telefonica_primary-00001689”, “0?sub-flp-2,s,1()”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:8] Set(“PJSIP/to_telefonica_primary-00001689”, “OUTNUM=+499119380003”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:9] Set(“PJSIP/to_telefonica_primary-00001689”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:10] Dial(“PJSIP/to_telefonica_primary-00001689”, “PJSIP/+499119380003@fronerisbc,300,T”) in new stack
[2021-02-09 21:41:49] VERBOSE[57644][C-00000b3c] app_dial.c: Called PJSIP/+499119380003@fronerisbc
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] app_dial.c: PJSIP/fronerisbc-0000168a is ringing
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] app_dial.c: PJSIP/fronerisbc-0000168a is ringing
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] app_dial.c: Everyone is busy/congested at this time (1:0/1/0)
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:11] Set(“PJSIP/to_telefonica_primary-00001689”, “CALLERID(number)=00447969776426”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:12] Set(“PJSIP/to_telefonica_primary-00001689”, “CALLERID(name)=+447969776426”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [tdial@ext-trunk:13] Hangup(“PJSIP/to_telefonica_primary-00001689”, “”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Spawn extension (ext-trunk, tdial, 13) exited non-zero on ‘PJSIP/to_telefonica_primary-00001689’
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] app_stack.c: PJSIP/to_telefonica_primary-00001689 Internal Gosub(crm-hangup,s,1) start
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:1] NoOp(“PJSIP/to_telefonica_primary-00001689”, “Sending Hangup to CRM”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:2] NoOp(“PJSIP/to_telefonica_primary-00001689”, “HANGUP CAUSE: 34”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:3] ExecIf(“PJSIP/to_telefonica_primary-00001689”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:4] NoOp(“PJSIP/to_telefonica_primary-00001689”, “MASTER CHANNEL: 1612903309.12060 = 1612903309.12060”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:5] GotoIf(“PJSIP/to_telefonica_primary-00001689”, “0?return”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:6] Set(“PJSIP/to_telefonica_primary-00001689”, “__CRM_HANGUP=1”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:7] AGI(“PJSIP/to_telefonica_primary-00001689”, “sangomacrm.agi”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] res_agi.c: <PJSIP/to_telefonica_primary-00001689>AGI Script sangomacrm.agi completed, returning 0
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] pbx.c: Executing [s@crm-hangup:8] Return(“PJSIP/to_telefonica_primary-00001689”, “”) in new stack
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] app_stack.c: Spawn extension (ext-trunk, tdial, 13) exited non-zero on ‘PJSIP/to_telefonica_primary-00001689’
[2021-02-09 21:41:50] VERBOSE[57644][C-00000b3c] app_stack.c: PJSIP/to_telefonica_primary-00001689 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
^C

a0429 · February 9, 2021, 8:53pm

I see the busy message in the SIP trace from the SBC and the below in the second call whilst the first call is ongoing.

[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: PJSIP/sbctrunk-00001688 is ringing
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: PJSIP/sbctrunk-00001688 is ringing
[2021-02-09 21:41:48] VERBOSE[57589][C-00000b3b] app_dial.c: Everyone is busy/congested at this time (1:0/1/0)

But the PBX does not send on the 486 message to our provider, instead it sends on the 503 message. I can send a full SIP trace if required to you personally?

lgaetz · February 9, 2021, 8:54pm

Please share call traces and verbose logs using pastebin.

a0429 · February 9, 2021, 9:03pm

Thanks Lorne - Done - https://pastebin.freepbx.org/view/fad1bbe4

billsimon · February 9, 2021, 9:17pm

If I understand right you have the SBC set up as a trunk. Do you happen to have the SBC trunk configured with “Continue if Busy” set to yes?

Stewart1 · February 9, 2021, 9:28pm

Is the 486 expected in normal call flow? IMO, annoying a customer with a busy signal is not a good idea.

If his party is on the phone, depending on your business you might send the call to a receptionist, voicemail, or a queue where the caller can choose to wait, be called back, or leave a message.

If the 486 is caused by insufficient channels, etc., fix that.

To many attempts that result in a busy signal is inviting the customer to go to a competitor.

a0429 · February 9, 2021, 10:04pm

The SBC is setup as a trunk yep correct.

The SBC “Continue if Busy” is set to no
The SIP provider is setup to continue if busy - if it gets a busy tone, it auto tries to send out of the secondary SIP trunk instead.

I just tried to set the SIP provider Continue if Busy to no and it made no difference. The 503 is sent to provider, and for some reason, they continue to send the call in even when a 503 has been sent.

Bacause the call comes in that way, it just spams with INVITES and the caller continues hearing ringing - which isnt good because they think they are connecting to the callee even when the callee is busy.

a0429 · February 9, 2021, 10:07pm

We need the 486 because we will have the users as part of a queue. If we add all SBC extensions in the queue setup, in theory it will never follow onto the next agent with any ring strategy, it will just sit and continue to call the agent.

486 busy should be sent in cases where no failover destination such as voicemail is set IMO so in theory the busy should be sent because there is no failover destination

billsimon · February 9, 2021, 10:36pm

I think it’s a bug in the dialplan logic that is followed when you set Trunk as a destination target.

Normal trunk dialing logic (when trunks are used in outbound routes) is somewhat sophisticated and looks at the reason an outbound call failed. On failure it either goes back into the dialplan to try another trunk (Continue if Busy) or it responds back to the caller according to the reason given downstream. ([macro-dialout-trunk] from /etc/asterisk/extensions_additional.conf)

When you set Trunk as a destination target it uses another part of the dialplan called [ext-trunk] which is not sophisticated… in fact it might be incomplete. It issues a Dial command for the trunk and whatever the result, follows it with a plain Hangup (no reason considered).

I am guessing that issuing a Hangup on a channel that is still ringing and hasn’t been answered results in the 503 response.

You might be able to work around this bug with a different call flow. What is the purpose of the SBC? Do you have endpoints registered to it?

a0429 · February 9, 2021, 10:41pm

Cheers. No - no endpoints configured as such. The SBC is an Opensips SBC which forwards the call to a Teams user using Direct Routing.

So normal test:
PSTN --> Extension with fm/fm to Teams user --> SBC --> Teams user

To take out the complexity and get to the bottom of the issue, I have disabled fm/fm to understand why the busy isnt working.

I have also tried setting the destination to the extension with a UCP forward, but the same thing happens everytime.

Happy to try another call flow?

Cheers…

billsimon · February 9, 2021, 10:50pm

Can you expand on that a bit? Where do you have the Teams/SBC trunk selected as a target?

a0429 · February 9, 2021, 10:59pm

As an inbound route, we have tried:

Sending the call to an extension with follow me onto the Teams number (which is caught by an outbound route to send it over the SBC (on prem) and onto Teams)
Sending the call straight to the SBC sip trunk
Sending the call to an extension with a UCP forward

billsimon · February 9, 2021, 11:02pm

Which of those three bullet points corresponds to the logs posted earlier? The second one (straight to the SBC SIP trunk) I believe?