FreePBX calling out over trunk NOT in dialplan upon congestion

tastech · October 17, 2018, 4:30pm

We have a specific outbound route we use for sending T38 traffic from a downstream switch to a T38 provider. T38 works fine and that is not the issue.

We have the dialplan set up based on caller ID, so the caller ID of the downstream switch handling fax traffic triggers that outbound route / dialplan and sends traffic out over it. We only have one outbound trunk set for this route, and that is the trunk for the T38 traffic.

It looks like when the call does not complete due to a ‘not in service number’, calls are then failing over to one of our other trunks, as if I had multiple trunks on this route set up for failover. That should not be happening - we don’t want it to bother trying a T38 call over any of our other carriers, we just want it to fail… So for this route, we only have the one trunk listed. Why would it try another trunk?

I have pasted that dialplan below (caller ID info changed) - and I know it is using that dialplan, as the first call attempt is placed over the T38 trunk (trunk 4) - and that trunk is ONLY being used in this route.

Then the logs show it moving on to dial out over trunk 2… We also don’t have ‘check to try next trunk’ enabled for the T38 trunk.

The dialplan for these calls is this:

[outrt-25] ; FaxingOut
exten => _+1NXXNXXXXXX,1,Macro(user-callerid,LIMIT,EXTERNAL,)

exten => _+1NXXNXXXXXX/1112223333,1,Macro(user-callerid,LIMIT,EXTERNAL,)
exten => _+1NXXNXXXXXX/1112223333,n,Gosub(sub-record-check,s,1(out,${EXTEN},never))
exten => _+1NXXNXXXXXX/1112223333,n,ExecIf($[ “${CALLEE_ACCOUNCODE}” != “” ] ?Set(CDR(accountcode)=${CALLEE_ACCOUNCODE}))
exten => _+1NXXNXXXXXX/1112223333,n,Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})})
exten => _+1NXXNXXXXXX/1112223333,n,ExecIf($["${KEEPCID}"!=“TRUE” & ${LEN(${TRUNKCIDOVERRIDE})}=0]?Set(TRUNKCIDOVERRIDE=“Example Company” <1112223333>))
exten => _+1NXXNXXXXXX/1112223333,n,Set(_NODEST=)
exten => _+1NXXNXXXXXX/1112223333,n,Macro(dialout-trunk,4,${EXTEN},off)
exten => _+1NXXNXXXXXX/1112223333,n,Macro(outisbusy,)

exten => _1NXXNXXXXXX,1,Macro(user-callerid,LIMIT,EXTERNAL,)

exten => _1NXXNXXXXXX/1112223333,1,Macro(user-callerid,LIMIT,EXTERNAL,)
exten => _1NXXNXXXXXX/1112223333,n,Gosub(sub-record-check,s,1(out,${EXTEN},never))
exten => _1NXXNXXXXXX/1112223333,n,ExecIf($[ “${CALLEE_ACCOUNCODE}” != “” ] ?Set(CDR(accountcode)=${CALLEE_ACCOUNCODE}))
exten => _1NXXNXXXXXX/1112223333,n,Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})})
exten => _1NXXNXXXXXX/1112223333,n,ExecIf($["${KEEPCID}"!=“TRUE” & ${LEN(${TRUNKCIDOVERRIDE})}=0]?Set(TRUNKCIDOVERRIDE=“Example Company” <1112223333>))
exten => _1NXXNXXXXXX/1112223333,n,Set(_NODEST=)
exten => _1NXXNXXXXXX/1112223333,n,Macro(dialout-trunk,4,+${EXTEN},off)
exten => _1NXXNXXXXXX/1112223333,n,Macro(outisbusy,)

exten => _NXXNXXXXXX,1,Macro(user-callerid,LIMIT,EXTERNAL,)

exten => _NXXNXXXXXX/1112223333,1,Macro(user-callerid,LIMIT,EXTERNAL,)
exten => _NXXNXXXXXX/1112223333,n,Gosub(sub-record-check,s,1(out,${EXTEN},never))
exten => _NXXNXXXXXX/1112223333,n,ExecIf($[ “${CALLEE_ACCOUNCODE}” != “” ] ?Set(CDR(accountcode)=${CALLEE_ACCOUNCODE}))
exten => _NXXNXXXXXX/1112223333,n,Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})})
exten => _NXXNXXXXXX/1112223333,n,ExecIf($["${KEEPCID}"!=“TRUE” & ${LEN(${TRUNKCIDOVERRIDE})}=0]?Set(TRUNKCIDOVERRIDE=“Example Company” <1112223333>))
exten => _NXXNXXXXXX/1112223333,n,Set(_NODEST=)
exten => _NXXNXXXXXX/1112223333,n,Macro(dialout-trunk,4,+1${EXTEN},off)
exten => _NXXNXXXXXX/1112223333,n,Macro(outisbusy,)

exten => _NXXXXXX,1,Macro(user-callerid,LIMIT,EXTERNAL,)

exten => _NXXXXXX/1112223333,1,Macro(user-callerid,LIMIT,EXTERNAL,)
exten => _NXXXXXX/1112223333,n,Gosub(sub-record-check,s,1(out,${EXTEN},never))
exten => _NXXXXXX/1112223333,n,ExecIf($[ “${CALLEE_ACCOUNCODE}” != “” ] ?Set(CDR(accountcode)=${CALLEE_ACCOUNCODE}))
exten => _NXXXXXX/1112223333,n,Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})})
exten => _NXXXXXX/1112223333,n,ExecIf($["${KEEPCID}"!=“TRUE” & ${LEN(${TRUNKCIDOVERRIDE})}=0]?Set(TRUNKCIDOVERRIDE=“Example Company” <1112223333>))
exten => _NXXXXXX/1112223333,n,Set(_NODEST=)
exten => _NXXXXXX/1112223333,n,Macro(dialout-trunk,4,+111${EXTEN},off)
exten => _NXXXXXX/1112223333,n,Macro(outisbusy,)

;–== end of [outrt-25] ==–;

FreePBX version 6.12.65-32
Asterisk version 11.21.2

PitzKey · October 17, 2018, 7:14pm

If you have only one Trunk in that outbound route and it’s still trying other Trunks, then this is likely a bug.

I understand that you are asking here for help with a custom dialplan, however, if you get this possible bug reported and fixed, you don’t need the dialplan.

P.S. Posting the version of Asterisk, FreePBX and the modules would be helpful if anyone here tries to reproduce this issues.

tastech · October 17, 2018, 7:52pm

Alright, I have the FreePBX and Asterisk versions at the bottom of the post, did not think about the modules - I am not certain which ones are involved in ringing the outbound call, which would they be?

PitzKey · October 17, 2018, 8:44pm

Woops. I missed that.

Both, Asterisk and FreePBX version you are using are EOL.
So no need for the module information since no bug fixes will be made…
Consider upgrading.

BlazeStudios · October 17, 2018, 10:16pm

Show us this actually happening. Post the log or a new debug of it.

tastech · October 18, 2018, 12:21am

Here is the log - there were several other calls happening at the same time but I think I got everything not related to this call deleted out. I had to replace certain values with fake ones.

The call is coming from a Freeswitch instance downstream of FreePBX. That is sending the call because it is required for use with our faxing software. That is why you will see ‘TrunktoFreeswitch’ in the logs.

‘T38carrier’ is the carrier being used for T38. Is the only trunk in this route, and should be the only one used. IP changed to 62.62.62.62.

‘VoiceCarrier’ is the trunk that the call is failing over to when is gets the failure on the T38 trunk (the call also fails there because the recipient of the fax did not realize the line was disconnected). That IP is changed to 82.82.82.82.

The sending caller ID is 1112223333, and the called party / recipient of the fax is 4445556666. In the dialstring you will see a prefix code of 9999. In practice that is a different code, and tells the T38 carrier to use a specific route for this traffic.

Here is the log:

[2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:04] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] netsock2.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] netsock2.c: [2018-10-17 09:52:05] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:10] VERBOSE[27933][C-0023b0bc] chan_sip.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] netsock2.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] netsock2.c: [2018-10-17 09:52:10] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:11] VERBOSE[27933][C-0023b0bd] netsock2.c: [2018-10-17 09:52:11] VERBOSE[27933][C-0023b0bd] netsock2.c: [2018-10-17 09:52:40] VERBOSE[27933][C-0023b0be] netsock2.c: [2018-10-17 09:52:40] VERBOSE[27933][C-0023b0be] netsock2.c: [2018-10-17 09:52:50] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:52] VERBOSE[27933][C-0023b0bc] chan_sip.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] app_dial.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:52] VERBOSE[23551][C-0023b0bc] file.c: [2018-10-17 09:52:54] VERBOSE[23551][C-0023b0bc] file.c: [2018-10-17 09:52:56] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:56] WARNING[23551][C-0023b0bc] [2018-10-17 09:52:56] VERBOSE[23551][C-0023b0bc] app_macro.c: [2018-10-17 09:52:56] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:56] VERBOSE[23551][C-0023b0bc] pbx.c: [2018-10-17 09:52:56] VERBOSE[23551][C-0023b0bc] pbx.c: – Executing [4445556666@from-internal:1] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/TrunktoFreeswitch-002e15ff”, “TOUCH_MONITOR=1539784324.6994873”) in new stack
– Executing [s@macro-user-callerid:2] Set(“SIP/TrunktoFreeswitch-002e15ff”, “AMPUSER=1112223333”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?Set(REALCALLERIDNUM=1112223333)”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/TrunktoFreeswitch-002e15ff”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/TrunktoFreeswitch-002e15ff”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?report”) in new stack
– Goto (macro-user-callerid,s,16)
– Executing [s@macro-user-callerid:16] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,30)
– Executing [s@macro-user-callerid:30] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CALLERID(number)=1112223333”) in new stack
– Executing [s@macro-user-callerid:31] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CALLERID(name)=fax”) in new stack
– Executing [s@macro-user-callerid:32] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CDR(cnum)=1112223333”) in new stack
– Executing [s@macro-user-callerid:33] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CDR(cnam)=fax”) in new stack
– Executing [s@macro-user-callerid:34] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CHANNEL(language)=en”) in new stack
– Executing [4445556666@from-internal:2] Gosub(“SIP/TrunktoFreeswitch-002e15ff”, “sub-record-check,s,1(out,4445556666,never)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“SIP/TrunktoFreeswitch-002e15ff”, “NOW=1539784324”) in new stack
– Executing [s@sub-record-check:4] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__DAY=17”) in new stack
– Executing [s@sub-record-check:5] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__MONTH=10”) in new stack
– Executing [s@sub-record-check:6] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__YEAR=2018”) in new stack
– Executing [s@sub-record-check:7] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__TIMESTR=20181017-095204”) in new stack
– Executing [s@sub-record-check:8] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__FROMEXTEN=1112223333”) in new stack
– Executing [s@sub-record-check:9] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/TrunktoFreeswitch-002e15ff”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “3?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?sub-record-check,out,1”) in new stack
– Goto (sub-record-check,out,1)
– Executing [out@sub-record-check:1] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “Outbound Recording Check from 1112223333 to 4445556666”) in new stack
– Executing [out@sub-record-check:2] Set(“SIP/TrunktoFreeswitch-002e15ff”, “RECMODE=”) in new stack
– Executing [out@sub-record-check:3] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?Goto(routewins)”) in new stack
– Goto (sub-record-check,out,7)
– Executing [out@sub-record-check:7] Gosub(“SIP/TrunktoFreeswitch-002e15ff”, “recordcheck,1(never,out,4445556666)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “Starting recording check against never”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“SIP/TrunktoFreeswitch-002e15ff”, “never”) in new stack
– Goto (sub-record-check,recordcheck,14)
– Executing [recordcheck@sub-record-check:14] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__REC_POLICY_MODE=NEVER”) in new stack
– Executing [recordcheck@sub-record-check:15] Goto(“SIP/TrunktoFreeswitch-002e15ff”, “stoprec”) in new stack
– Goto (sub-record-check,recordcheck,25)
– Executing [recordcheck@sub-record-check:25] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “Stopping recording: out, 4445556666”) in new stack
– Executing [recordcheck@sub-record-check:26] Set(“SIP/TrunktoFreeswitch-002e15ff”, “__REC_STATUS=STOPPED”) in new stack
– Executing [recordcheck@sub-record-check:27] System(“SIP/TrunktoFreeswitch-002e15ff”, “/var/lib/asterisk/bin/stoprecording.php “SIP/TrunktoFreeswitch-002e15ff””) in new stack
– Executing [recordcheck@sub-record-check:28] Return(“SIP/TrunktoFreeswitch-002e15ff”, “”) in new stack
– Executing [out@sub-record-check:8] Return(“SIP/TrunktoFreeswitch-002e15ff”, “”) in new stack
– Executing [4445556666@from-internal:3] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0 ?Set(CDR(accountcode)=)”) in new stack
– Executing [4445556666@from-internal:4] Set(“SIP/TrunktoFreeswitch-002e15ff”, “MOHCLASS=default”) in new stack
– Executing [4445556666@from-internal:5] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?Set(TRUNKCIDOVERRIDE=“Client Name” <1112223333>)”) in new stack
– Executing [4445556666@from-internal:6] Set(“SIP/TrunktoFreeswitch-002e15ff”, “_NODEST=”) in new stack
– Executing [4445556666@from-internal:7] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “dialout-trunk,4,+14445556666,off”) in new stack
– Executing [s@macro-dialout-trunk:1] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_TRUNK=4”) in new stack
– Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?sub-pincheck,s,1()”) in new stack
– Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?disabletrunk,1”) in new stack
– Executing [s@macro-dialout-trunk:4] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_NUMBER=+14445556666”) in new stack
– Executing [s@macro-dialout-trunk:5] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
– Executing [s@macro-dialout-trunk:6] Set(“SIP/TrunktoFreeswitch-002e15ff”, “OUTBOUND_GROUP=OUT_4”) in new stack
– Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?nomax”) in new stack
– Goto (macro-dialout-trunk,s,9)
– Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?skipoutcid”) in new stack
– Executing [s@macro-dialout-trunk:10] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_TRUNK_OPTIONS=Tt”) in new stack
– Executing [s@macro-dialout-trunk:11] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “outbound-callerid,4”) in new stack
– Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERPRES()=)”) in new stack
– Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(REALCALLERIDNUM=1112223333)”) in new stack
– Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?normcid”) in new stack
– Goto (macro-outbound-callerid,s,6)
– Executing [s@macro-outbound-callerid:6] Set(“SIP/TrunktoFreeswitch-002e15ff”, “USEROUTCID=”) in new stack
– Executing [s@macro-outbound-callerid:7] Set(“SIP/TrunktoFreeswitch-002e15ff”, “EMERGENCYCID=”) in new stack
– Executing [s@macro-outbound-callerid:8] Set(“SIP/TrunktoFreeswitch-002e15ff”, “TRUNKOUTCID=<1112223333>”) in new stack
– Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?trunkcid”) in new stack
– Goto (macro-outbound-callerid,s,14)
– Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?Set(CALLERID(all)=<1112223333>)”) in new stack
– Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERID(all)=)”) in new stack
– Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?Set(CALLERID(all)=Client Name <1112223333>)”) in new stack
– Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
– Executing [s@macro-outbound-callerid:18] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CDR(outbound_cnum)=1112223333”) in new stack
– Executing [s@macro-outbound-callerid:19] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CDR(outbound_cnam)=Client Name”) in new stack
– Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?sub-flp-4,s,1()”) in new stack
– Executing [s@macro-dialout-trunk:13] Set(“SIP/TrunktoFreeswitch-002e15ff”, “OUTNUM=9999+14445556666”) in new stack
– Executing [s@macro-dialout-trunk:14] Set(“SIP/TrunktoFreeswitch-002e15ff”, “custom=SIP/T38carrierFaxOut”) in new stack
– Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)”) in new stack
– Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))”) in new stack
– Executing [s@macro-dialout-trunk:17] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “dialout-trunk-predial-hook,”) in new stack
– Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/TrunktoFreeswitch-002e15ff”, “”) in new stack
– Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?bypass,1”) in new stack
– Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CONNECTEDLINE(num,i)=+14445556666)”) in new stack
– Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CONNECTEDLINE(name,i)=CID:1112223333)”) in new stack
– Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?customtrunk”) in new stack
– Executing [s@macro-dialout-trunk:22] Dial(“SIP/TrunktoFreeswitch-002e15ff”, “SIP/T38carrierFaxOut/9999+14445556666,300,Tt”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP/T38carrierFaxOut/9999+14445556666
– Got SIP response 504 “Server Time-out” back from 62.62.62.62:5060
– SIP/T38carrierFaxOut-002e1600 is circuit-busy
== Everyone is busy/congested at this time (1:0/1/0)
– Executing [s@macro-dialout-trunk:23] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 102”) in new stack
– Executing [s@macro-dialout-trunk:24] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?continue,1:s-CONGESTION,1”) in new stack
– Goto (macro-dialout-trunk,s-CONGESTION,1)
– Executing [s-CONGESTION@macro-dialout-trunk:1] Set(“SIP/TrunktoFreeswitch-002e15ff”, “RC=102”) in new stack
– Executing [s-CONGESTION@macro-dialout-trunk:2] Goto(“SIP/TrunktoFreeswitch-002e15ff”, “102,1”) in new stack
– Goto (macro-dialout-trunk,102,1)
– Executing [102@macro-dialout-trunk:1] Goto(“SIP/TrunktoFreeswitch-002e15ff”, “continue,1”) in new stack
– Goto (macro-dialout-trunk,continue,1)
– Executing [continue@macro-dialout-trunk:1] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 102 - failing through to other trunks”) in new stack
– Executing [continue@macro-dialout-trunk:2] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CALLERID(number)=”) in new stack
– Executing [4445556666@from-internal:8] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “dialout-trunk,2,+14445556666,off”) in new stack
– Executing [s@macro-dialout-trunk:1] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_TRUNK=2”) in new stack
– Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?sub-pincheck,s,1()”) in new stack
– Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?disabletrunk,1”) in new stack
– Executing [s@macro-dialout-trunk:4] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_NUMBER=+14445556666”) in new stack
– Executing [s@macro-dialout-trunk:5] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
– Executing [s@macro-dialout-trunk:6] Set(“SIP/TrunktoFreeswitch-002e15ff”, “OUTBOUND_GROUP=OUT_2”) in new stack
– Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?nomax”) in new stack
– Goto (macro-dialout-trunk,s,9)
– Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?skipoutcid”) in new stack
– Executing [s@macro-dialout-trunk:10] Set(“SIP/TrunktoFreeswitch-002e15ff”, “DIAL_TRUNK_OPTIONS=Tt”) in new stack
– Executing [s@macro-dialout-trunk:11] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “outbound-callerid,2”) in new stack
– Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERPRES()=)”) in new stack
– Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(REALCALLERIDNUM=)”) in new stack
– Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?normcid”) in new stack
– Goto (macro-outbound-callerid,s,6)
– Executing [s@macro-outbound-callerid:6] Set(“SIP/TrunktoFreeswitch-002e15ff”, “USEROUTCID=”) in new stack
– Executing [s@macro-outbound-callerid:7] Set(“SIP/TrunktoFreeswitch-002e15ff”, “EMERGENCYCID=”) in new stack
– Executing [s@macro-outbound-callerid:8] Set(“SIP/TrunktoFreeswitch-002e15ff”, “TRUNKOUTCID=”) in new stack
– Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?trunkcid”) in new stack
– Goto (macro-outbound-callerid,s,14)
– Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERID(all)=)”) in new stack
– Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERID(all)=)”) in new stack
– Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “1?Set(CALLERID(all)=Client Name <1112223333>)”) in new stack
– Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
– Executing [s@macro-outbound-callerid:18] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CDR(outbound_cnum)=1112223333”) in new stack
– Executing [s@macro-outbound-callerid:19] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CDR(outbound_cnam)=Client Name”) in new stack
– Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?sub-flp-2,s,1()”) in new stack
– Executing [s@macro-dialout-trunk:13] Set(“SIP/TrunktoFreeswitch-002e15ff”, “OUTNUM=+14445556666”) in new stack
– Executing [s@macro-dialout-trunk:14] Set(“SIP/TrunktoFreeswitch-002e15ff”, “custom=SIP/VoiceCarrierOut”) in new stack
– Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)”) in new stack
– Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))”) in new stack
– Executing [s@macro-dialout-trunk:17] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “dialout-trunk-predial-hook,”) in new stack
– Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/TrunktoFreeswitch-002e15ff”, “”) in new stack
– Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?bypass,1”) in new stack
– Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CONNECTEDLINE(num,i)=+14445556666)”) in new stack
– Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?Set(CONNECTEDLINE(name,i)=CID:1112223333)”) in new stack
– Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?customtrunk”) in new stack
– Executing [s@macro-dialout-trunk:22] Dial(“SIP/TrunktoFreeswitch-002e15ff”, “SIP/VoiceCarrierOut/+14445556666,300,Tt”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP/VoiceCarrierOut/+14445556666
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– SIP/VoiceCarrierOut-002e1601 is ringing
– Got SIP response 480 “Temporarily not available” back from 82.82.82.82:5060
– SIP/VoiceCarrierOut-002e1601 is circuit-busy
== Everyone is busy/congested at this time (1:0/1/0)
– Executing [s@macro-dialout-trunk:23] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 19”) in new stack
– Executing [s@macro-dialout-trunk:24] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?continue,1:s-CONGESTION,1”) in new stack
– Goto (macro-dialout-trunk,s-CONGESTION,1)
– Executing [s-CONGESTION@macro-dialout-trunk:1] Set(“SIP/TrunktoFreeswitch-002e15ff”, “RC=19”) in new stack
– Executing [s-CONGESTION@macro-dialout-trunk:2] Goto(“SIP/TrunktoFreeswitch-002e15ff”, “19,1”) in new stack
– Goto (macro-dialout-trunk,19,1)
– Executing [19@macro-dialout-trunk:1] Goto(“SIP/TrunktoFreeswitch-002e15ff”, “continue,1”) in new stack
– Goto (macro-dialout-trunk,continue,1)
– Executing [continue@macro-dialout-trunk:1] NoOp(“SIP/TrunktoFreeswitch-002e15ff”, “TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 19 - failing through to other trunks”) in new stack
– Executing [continue@macro-dialout-trunk:2] Set(“SIP/TrunktoFreeswitch-002e15ff”, “CALLERID(number)=”) in new stack
– Executing [4445556666@from-internal:9] Macro(“SIP/TrunktoFreeswitch-002e15ff”, “outisbusy,”) in new stack
– Executing [s@macro-outisbusy:1] Progress(“SIP/TrunktoFreeswitch-002e15ff”, “”) in new stack
– Executing [s@macro-outisbusy:2] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?emergency,1”) in new stack
– Executing [s@macro-outisbusy:3] GotoIf(“SIP/TrunktoFreeswitch-002e15ff”, “0?intracompany,1”) in new stack
– Executing [s@macro-outisbusy:4] Playback(“SIP/TrunktoFreeswitch-002e15ff”, “all-circuits-busy-now&pls-try-call-later, noanswer”) in new stack
– <SIP/TrunktoFreeswitch-002e15ff> Playing ‘all-circuits-busy-now.ulaw’ (language ‘en’)
– <SIP/TrunktoFreeswitch-002e15ff> Playing ‘pls-try-call-later.ulaw’ (language ‘en’)
– Executing [s@macro-outisbusy:5] Congestion(“SIP/TrunktoFreeswitch-002e15ff”, “20”) in new stack
channel.c: Prodding channel ‘SIP/TrunktoFreeswitch-002e15ff’ failed
== Spawn extension (macro-outisbusy, s, 5) exited non-zero on ‘SIP/TrunktoFreeswitch-002e15ff’ in macro ‘outisbusy’
== Spawn extension (from-internal, 4445556666, 9) exited non-zero on ‘SIP/TrunktoFreeswitch-002e15ff’
– Executing [h@from-internal:1] Hangup(“SIP/TrunktoFreeswitch-002e15ff”, “”) in new stack
== Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/TrunktoFreeswitch-002e15ff’

BlazeStudios · October 18, 2018, 12:33am

This isn’t an Outbound Route issue. If you have multiple “outgoing” trunks then they will be tried with a server error is received. In this case you are getting a 504 Server Timeout (that is rather concerning) so the system is going to try to complete the call with the next trunk that follows the original trunk.

The “Match Sequence” in the Outbound Route is to make that Outbound use that sequence of trunks when a match is made.

Basically, if your T.38 providers network wasn’t timing out this wouldn’t be an issue. A 504 means that they never sent 100 Trying reply to your INVITE. That has nothing to do with a number not being in service. You’re confusing generic errors messages on the PBX for what the actual issue is. If the number was something that didn’t exist or was not in service your provider would send back a 4XX reply like 404 Not Found or 484 Incomplete Address.

tastech · October 18, 2018, 1:00am

BlazeStudios:

tastech:

Executing [continue@macro-dialout-trunk:1]

This isn’t an Outbound Route issue. If you have multiple “outgoing” trunks then they will be tried with a server error is received. In this case you are getting a 504 Server Timeout (that is rather concerning) so the system is going to try to complete the call with the next trunk that follows the original trunk.

The “Match Sequence” in the Outbound Route is to make that Outbound use that sequence of trunks when a match is made.

Basically, if your T.38 providers network wasn’t timing out this wouldn’t be an issue. A 504 means that they never sent 100 Trying reply to your INVITE. That has nothing to do with a number not being in service. You’re confusing generic errors messages on the PBX for what the actual issue is. If the number was something that didn’t exist or was not in service your provider would send back a 4XX reply like 404 Not Found or 484 Incomplete Address.

This carrier does LCR and so they have about 10 seconds to get back to us with a timeout. What is the default timeout for not getting a response in FreePBX and could it be considering it a timeout before the carrier has gotten back to us? We do sometimes see strange behavior when the destination number is a nonworking number.

That aside, when you say ‘if it wasn’t timing out it wouldn’t be an issue’… So if I have:

10 trunks in the system, labelled 1 through 10
A call matches a route that only has trunk 2 in its trunk sequence, no others.
The server at the other end of trunk 2 is down and thus times out

Then the call is going to try trunks 3, 4, 5, etc. until either the call completes or it gets a busy / unavailable, etc.? We have certain traffic we never want to send out certain trunks, and that’s why we use match sequences in the routes to restrict certain outbound traffic to certain routes. What is the purpose of picking another trunk not listed in the trunk sequence for that route? And is there any way to prevent that behavior?

BlazeStudios · October 18, 2018, 1:12am

Create a “blackhole” trunk and make it the last in the sequence.

tonyclewis · October 18, 2018, 1:21am

Tom are you even reading what the OP is saying? Your answers make no sense based on what the OP is saying. He has said a couple times the route only has 1 trunk in it. I think you need to slow down your answers lately in our threads. Yiir doing alot of incorrect answers by not taking the time to read things.

Back to the issue here the only thing I can come up with is it’s grabbing a different route not the one you think it’s grabbing that only has 1 trunk. The way the dialplan works once it finds a match in a route even if the call fails it can’t leave the route and go find a new route.

tastech · October 18, 2018, 1:49am

I thought it was a match to another route at first too, but I went through and confirmed that the single trunk in use for this route is not used by any other routes. Also, I verified it is the only trunk with the prefix being placed in the dial string. The CDR reports also show this trunk being used, so everything I can see points to the correct route being used. I’m not that familiar with the verbose logs but I was hoping to see in there confirmation of the route selected, but I am not seeing any line jumping out at me saying which route is in use? Is there a log item created when the route is matched?

I did create a blackhole trunk as described in the meantime with a custom dial string of:

Local/congestion@app-blackhole

And put that after the T38 trunk in the trunk sequence - it didn’t seem to hurt to try…

Unfortunately the recipient of the call/fax resolved the issue with their telco after I reported it to them today, and now the call is completing and the fax at the other end is picking up, so I wouldn’t be able to confirm any changes worked until the next time this carrier times out.

lgaetz · October 18, 2018, 1:53am

Enable NoOp traces in Advanced Settings and the outroute name gets logged.

tastech · October 18, 2018, 2:02am

From a search (actually is a post from you in 2015) ‘1’ seems to be an adequate level, or should it be higher?

Even though I might not be able to replicate the timeout, I can make the same call from the same downstream server, and see the route name. That will in theory mean it was using the route before (I didn’t change the match strings or any route order on the PBX). And it will help give me more info if it occurs in the future.

Thank you all for the help!

lgaetz · October 18, 2018, 3:13am

BlazeStudios · October 18, 2018, 3:36am

There is a lot of irony in that statement but anyhoo. I did read what was posted and the debug I asked for based on what I read showed something different than what the OP was saying in their original post. That happens sometimes. That being said, it did prompt me to go back and look at the original post which made me catch something I thought was kind of weird.

While they all have this same thing happening, this is the pattern that the debug showed to be matching. My question is, where did this single line come from?

There’s no continuation of dialplan for that context,exten. There should be the same amount of dialplan for this pattern as there are with those with the callerid matches. As far as I can tell all it’s really doing it matching against the NXXNXXXXXX (because there’s no CID match, it will match against any CID) and running the usercallerid macro and then continuing on to hit the digit/CID match that follows.

Seems like the Outbound Routes are being generated funny. Do your other Outbound Routes end up showing this same pattern? Or do they all generate the proper amount of dialplan lines to go with them?

tastech · October 18, 2018, 12:55pm

It looks like every single dialpattern of every single route starts with:

Then subsequently for the rest of the entries the 1 is replaced with n for no caller ID match or whatever caller ID number I am looking for in that pattern.

Sometimes there is a carriage return between that line and the rest of the dialpattern, in other cases there is not.

I have never edited dialpatterns manually, just used the GUI to generate these.

BlazeStudios · October 18, 2018, 12:57pm

Right and that means they are being generated strangely. Also the “n” stands for “next” as in “next priority in the dialplan”. Not “n for no CallerID”

tastech · October 18, 2018, 1:28pm

I can confirm that the calls are going out the correct route:

[2018-10-18 09:00:11] VERBOSE[29021][C-0023c317] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e71”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:17] VERBOSE[29032][C-0023c318] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e73”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:24] VERBOSE[29066][C-0023c319] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e76”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:29] VERBOSE[29077][C-0023c31b] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e7a”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:35] VERBOSE[29087][C-0023c31d] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e7d”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:41] VERBOSE[29100][C-0023c320] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e83”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:47] VERBOSE[29109][C-0023c321] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e85”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:52] VERBOSE[29124][C-0023c323] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e88”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:00:59] VERBOSE[29134][C-0023c324] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e8b”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:01:05] VERBOSE[29162][C-0023c326] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e8d”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:01:10] VERBOSE[29171][C-0023c327] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e8f”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:01:16] VERBOSE[29195][C-0023c328] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e91”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:01:27] VERBOSE[29216][C-0023c32a] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e94”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:01:48] VERBOSE[29252][C-0023c32f] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2e9d”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:04:16] VERBOSE[29509][C-0023c33f] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2eb4”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:05:13] VERBOSE[29598][C-0023c345] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2ebd”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:05:18] VERBOSE[29607][C-0023c346] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2ebf”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:05:25] VERBOSE[29616][C-0023c347] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2ec1”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:05:31] VERBOSE[29643][C-0023c34a] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2ec6”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:05:36] VERBOSE[29663][C-0023c34e] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2ece”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:06:43] VERBOSE[29776][C-0023c355] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2edb”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:10:10] VERBOSE[30128][C-0023c364] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2ef1”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:11:12] VERBOSE[30209][C-0023c36b] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2efb”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:14:15] VERBOSE[30531][C-0023c378] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2f0f”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:15:12] VERBOSE[30618][C-0023c37c] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2f15”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:16:12] VERBOSE[30737][C-0023c381] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2f1d”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:17:03] VERBOSE[30810][C-0023c386] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2f25”, “TRACE Calling Out Route: FaxingOut”) in new stack
[2018-10-18 09:18:13] VERBOSE[30958][C-0023c38d] pbx.c: – Executing [##########@from-internal:3] NoOp(“SIP/TrunktoFreeswitch-002e2f31”, “TRACE Calling Out Route: FaxingOut”) in new stack

BlazeStudios · October 18, 2018, 1:46pm

And now for the fun part because if this is a bug or something that will require actual support then you’re pretty much in a corner. FreePBX 12 and most certainly, Asterisk 11 are End of Life and are no longer supported.

So if the blackhole trunk is working as a fix that might be your only option at this point.

tastech · October 18, 2018, 2:14pm

Yep I am long past needing to upgrade, I am migrating to a fresh install but the volume going through this machine and other projects have put it off.

I just wanted to make sure I was understanding the issue, how the routes should work, and to make sure I wasn’t programming them wrong. I have the blackhole trunk in place and will watch for traffic going out over that secondary trunk (the one not assigned to the route) to see if that resolves the issue.

Luckily when the T38 trunk failed and the call went out over the other provider, that call failed (since it was a nonworking number) and I got an email alert from the provider, so I should know if it happens again.

Thanks again everyone for the help.