Outbound calling doesn't work

Hey guys, I’m having a weird problem with one of our PBXs. It’s running FreePBX 14.0.1.4, and VoicePules is my SIP provider. Inbound calling and internal calls work fine, but any calls to the outside world fail saying the call cannot be completed as dialed. This WAS working and then spontaneously stopped. When I run asterisk -RvvvvvT and make a test call here’s what I see:

 == Using SIP RTP TOS bits 184
 == Using SIP RTP CoS mark 5
       > 0x2cd3f60 -- Strict RTP learning after remote address set to: 10.99.79.10:8000
    -- Executing [MYCELL#@from-internal:1] Macro("SIP/503-00000011", "user-callerid,LIMIT") in new stack
    -- Executing [s@macro-user-callerid:1] Set("SIP/503-00000011", "TOUCH_MONITOR=1507314122.17") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/503-00000011", "AMPUSER=503") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/503-00000011", "0?report") in new stack
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/503-00000011", "1?Set(__REALCALLERIDNUM=503)") in new stack
    -- Executing [s@macro-user-callerid:5] Set("SIP/503-00000011", "AMPUSER=503") in new stack
    -- Executing [s@macro-user-callerid:6] GotoIf("SIP/503-00000011", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/503-00000011", "AMPUSERCIDNAME=jordan.pesavento") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("SIP/503-00000011", "0?report") in new stack
    -- Executing [s@macro-user-callerid:9] Set("SIP/503-00000011", "AMPUSERCID=503") in new stack
    -- Executing [s@macro-user-callerid:10] Set("SIP/503-00000011", "__DIAL_OPTIONS=Ttr") in new stack
    -- Executing [s@macro-user-callerid:11] Set("SIP/503-00000011", "CALLERID(all)="jordan.pesavento" <503>") in new stack
    -- Executing [s@macro-user-callerid:12] GotoIf("SIP/503-00000011", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:13] ExecIf("SIP/503-00000011", "1?Set(GROUP(concurrency_limit)=503)") in new stack
    -- Executing [s@macro-user-callerid:14] ExecIf("SIP/503-00000011", "0?Set(CHANNEL(language)=)") in new stack
    -- Executing [s@macro-user-callerid:15] GotoIf("SIP/503-00000011", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("SIP/503-00000011", "CALLERID(number)=503") in new stack
    -- Executing [s@macro-user-callerid:30] Set("SIP/503-00000011", "CALLERID(name)=user.name") in new stack
    -- Executing [s@macro-user-callerid:31] GotoIf("SIP/503-00000011", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:32] Set("SIP/503-00000011", "CDR(cnam)=user.name") in new stack
    -- Executing [s@macro-user-callerid:33] Set("SIP/503-00000011", "CDR(cnum)=503") in new stack
    -- Executing [s@macro-user-callerid:34] Set("SIP/503-00000011", "CHANNEL(language)=en") in new stack
    -- Executing [MYCELL#@from-internal:2] Set("SIP/503-00000011", "ROUTEUSER=503") in new stack
    -- Executing [MYCELL#@from-internal:3] Set("SIP/503-00000011", "ROUTEUSER=503") in new stack
    -- Executing [MYCELL#@from-internal:4] GotoIf("SIP/503-00000011", "1?notblind") in new stack
    -- Goto (from-internal,MYCELL#,7)
    -- Executing [MYCELL#@from-internal:7] GotoIf("SIP/503-00000011", "1?restrictedroute-cfcd208495d565ef66e7dff9f98764da,MYCELL#,2:outbound-allroutes,MYCELL#,2") in new stack
    -- Goto (restrictedroute-cfcd208495d565ef66e7dff9f98764da,MYCELL#,2)
    -- Channel 'SIP/503-00000011' sent to invalid extension: context,exten,priority=restrictedroute-cfcd208495d565ef66e7dff9f98764da,MYCELL#,2
    -- Executing [i@restrictedroute-cfcd208495d565ef66e7dff9f98764da:1] Goto("SIP/503-00000011", "bad-number,s,1") in new stack
    -- Goto (bad-number,s,1)
    -- Executing [s@bad-number:1] Goto("SIP/503-00000011", "11,1") in new stack
    -- Goto (bad-number,11,1)
    -- Executing [11@bad-number:1] ResetCDR("SIP/503-00000011", "") in new stack
    -- Executing [11@bad-number:2] NoCDR("SIP/503-00000011", "") in new stack
    -- Executing [11@bad-number:3] Progress("SIP/503-00000011", "") in new stack
    -- Executing [11@bad-number:4] Wait("SIP/503-00000011", "1") in new stack
       > 0x2cd3f60 -- Strict RTP switching source address to 50.246.204.75:59572
    -- Executing [11@bad-number:5] Playback("SIP/503-00000011", "silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer") in new stack
    -- <SIP/503-00000011> Playing 'silence/1.ulaw' (language 'en')
       > 0x2cd3f60 -- Strict RTP learning complete - Locking on source address 50.246.204.75:59572
    -- <SIP/503-00000011> Playing 'cannot-complete-as-dialed.ulaw' (language 'en')
    -- <SIP/503-00000011> Playing 'check-number-dial-again.ulaw' (language 'en')
    -- Executing [11@bad-number:6] Wait("SIP/503-00000011", "1") in new stack
    -- Executing [11@bad-number:7] Congestion("SIP/503-00000011", "20") in new stack
[2017-10-06 12:22:10] WARNING[145465][C-0000019b]: channel.c:4861 ast_prod: Prodding channel 'SIP/503-00000011' failed
  == Spawn extension (bad-number, 11, 7) exited non-zero on 'SIP/503-00000011'

I would think this means I have a problem with my outbound routes, but I can’t find what it is. I’ve compared it to another PBX we have that’s working fine and the routes look exactly the same. See attached:

Any ideas what’s going wrong here?

Well I think I figured it out. Apparently having the outbound route time condition set to “Permanent Route” isn’t working. If I create a Time Group that’s from 00:00 to 23:59 and assign that the calls go through.

So I guess the next questions is if this is a problem in FreePBX 14 (permanent route works fine on my other 4 PBXs that are on 13) or is there something busted with my install?

While it might have fixed your problem, I don’t think it’s the solution.

There’s something else going on here that we need to skull out. Changing the time condition to a set time like this shouldn’t affect the way the route is processed.

If I had to guess, I’d say the “permanent route” default is broken and instead of marking “always” it’s marking never. Setting a defined time makes the route available during that time.

Do you have any ideas on what I could do to troubleshoot further?

I’d start by submitting a ticket to get the developers to look at it too. Most people use permanent time conditions, so it might be something peculiar to your installation or the version you’re using.

Unless you can reproduce this and can get a call trace, a ticket is premature. I can’t reproduce this, and if all outbound calling was broken until making arbitrary changes to time groups, both the forum and issue tracker would be flooded with reports.

1 Like

Not sure if it matters, but I saw this bug on the tracker which is not me, but is reporting the exact same issue. So it looks like, while not widespread, the issue isn’t one-off either.

https://issues.freepbx.org/browse/FREEPBX-15681?jql=text%20~%20"permanent%20route"

Looks similar, but user did not include any details to allow us to understand the method of the failure and does not appear to have followed the recommendation to bring it up here.

Can you reproduce this issue?

I have not recreated it on a fresh install, but if I turn the time condition on the route back to “Permanent” then it does break the calling again.

can you attach a call trace of a failed call to the ticket you linked?

https://wiki.freepbx.org/display/SUP/Providing+Great+Debug#ProvidingGreatDebug-AsteriskLogs

Well, thank you guys for the answer, especially because i have had the same problem, and i thought i’ll never be able to solve it!:slight_smile:

1 Like