All circuits are busy - unsure of how to diagnose cause


(Adam) #1

Hi all,

I’m very new to FreePBX (only deployed one instance into production), and it seems to be working fine most of the time, except that it has started to occasionally give the message “all circuits are busy”. I have tried googling around to see if I can find the issue, but it would appear that this is an issue with multiple causes, and I am unsure of how to go about diagnosing my specific issue. Thus, I have turned to the community for help. I would like to post my log files, but attempting to do so gives me the message that “new users can’t post links”. If someone lets me know how to circumvent this, I will be happy to do so. Thanks in advance!


(Chris Dolese) #2

if able to repro at will you can do it live with sngrep along with the asterisk cli - those should provide some hints

otherwise set up some rolling tcpdump and find the full logs if they havent been rotated out on next report

could be other things like routing - any patterns with the failures ??


(Adam) #3

Hi Chris, thanks for your reply.

Unfortunately, I cannot reproduce at will. A high number of the calls succeed (>95%). The issue only strikes once or twice a day.

The only pattern with regard to the failure that I can determine is that it appears to have only struck during an outbound call. Interestingly, it also appears to occur when the call has been answered, that is, someone on the other end will pick up, and then the issue will happen.

Could you instruct me as to how to set up a rolling tcpdump?

Kind regards!

EDIT: I spoke with the receptionist, and she said that it has both occurred immediately after dialing outbound and also in the middle of an outbound call.


(Shackbill) #4

FYI… Apologies for hijacking this thread but we just had the same problem about 10 minutes ago 2 calls then dialed again. This is our first day we ported and we have 4 trunks with bursting configured. also, nobody else was in a call at the time.

Edit: This is what we saw in the log.

[2019-09-30 12:16:03] VERBOSE[3745][C-000000f0] app_macro.c: Spawn extension (macro-outisbusy, s, 5) exited non-zero on ‘SIP/29-00000210’ in macro ‘outisbusy’
[2019-09-30 12:27:34] VERBOSE[6512][C-000000f5] app_dial.c: SIP/fpbx-1-hWiVtEovHQUP-0000021b is circuit-busy
[2019-09-30 12:27:34] VERBOSE[6512][C-000000f5] app_dial.c: Everyone is busy/congested at this time (1:0/1/0)

Blockquote


(Adam) #5

This is what I see in my logs:

Blockquote
[2019-09-30 09:12:12] WARNING[135511] taskprocessor.c: The ‘pjsip/mwi-00000056’ task processor queue reached 500 scheduled tasks again.
[2019-09-30 09:12:12] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:12] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:12] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:12] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:12] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:13] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:13] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:13] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:13] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:13] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:13] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:14] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:14] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:15] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:15] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:16] NOTICE[33533] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:61234’ (callid: 1778808826-736225685-766470190) - N$
[2019-09-30 09:12:16] NOTICE[182647] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:63159’ (callid: 1760169304-857196628-1430236312) -$
[2019-09-30 09:12:17] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:17] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:17] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:17] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:20] NOTICE[12437] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:56453’ (callid: 1847043829-853197371-1712916011) - $
[2019-09-30 09:12:20] NOTICE[51839] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:56490’ (callid: 869700288-951134845-931522842) - No$
[2019-09-30 09:12:22] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:22] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:22] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:22] NOTICE[190495] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:61776’ (callid: 1305024210-1256634962-1741066750) $
[2019-09-30 09:12:22] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:26] NOTICE[194004] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:55108’ (callid: 1800624010-1298507258-1066190204) $
[2019-09-30 09:12:28] NOTICE[182647] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:57944’ (callid: 992921823-203176437-1141057640) - $
[2019-09-30 09:12:29] NOTICE[12437] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:60445’ (callid: 1346164805-1700052619-1563754000) -$
[2019-09-30 09:12:32] NOTICE[51839] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:53259’ (callid: 1986963049-706770983-938531421) - N$
[2019-09-30 09:12:32] NOTICE[190495] res_pjsip/pjsip_distributor.c: Request ‘INVITE’ from ‘sip:VoIP@198.53.193.72’ failed for ‘46.166.148.210:53663’ (callid: 799787363-424634247-1417846572) - $
[2019-09-30 09:12:32] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:32] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/ThinkTel-000011f0 is making progress passing it to PJSIP/1001-000011ef
[2019-09-30 09:12:33] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:33] VERBOSE[104740][C-000005f4] app_dial.c: PJSIP/1001-000011ef requested media update control 26, passing it to PJSIP/ThinkTel-000011f0
[2019-09-30 09:12:33] VERBOSE[104740][C-000005f4] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
Blockquote


(Molly Mae) #6

Are you using SIPStation? And do you have concurrency bursting enabled? Each trunk allows one inbound or outbound call at a time. With concurrency bursting, you can have multiple calls per trunk for a per minute charge.

I had that issue previously.

I’m certain there could be other reasons, however.


(Dave Burgess) #7

This indicates you are using the wrong MWI notification. Check the archives for more.

This can cause a lot of issues, including the PBX suddenly catatonic, so you might want to look at it.

These look like either a bad server address (are you using names or real IP addresses?) or a trunk limit failing.

Every failing call is going to the same IP address (46.166.148.210) - are they set up to handle your incoming calls?


(Adam) #8

Hi Dave,

To my knowledge, that IP address has nothing to do with my SIP Trunk configuration. My provider uses IP address 208.68.17.52, so I have no idea where those entries are coming from or why they are there.

I googled around for information on MWI notifications; they are configured on a per-extension basis correct? So do I need to be checking a setting on the actual physical phone?

I apologize for my lack of knowledge in this area; I came to FreePBX from 3CX, which took care of all of the correct configuration for me, so I’m not super familiar with the intricacies, or indeed terminology, of phone systems.


(Dave Burgess) #9

Except that’s where some of your calls are going. Once again, are you configuring your trunk with IP addresses or server names? This could be an errant DNS entry making its way back into your phone system and messing you up.

Issue with Polycom IP330 freezing has a good discussion on the topic.

Don’t worry about it. Just remember that the forum has been here for a long time and its very seldom that a new problem comes up. The search button in the top right corner of the screen can provide a lot of information - sometimes, too much. If you’re not sure what to ask, ask what you are sure of and we’ll try to get you squared away.


(Adam) #10

Hi Dave,

The trunk is being configured with a DNS entry - edm.trk.tprm.ca.

Based on the log, it appeared to me that those requests for invites and such looked like they were coming into my system, whereas the registration request I am making is outbound. Hence why I believe I shouldn’t be receiving any such requests at all.

We are behind a firewall in this network, so the Sangoma firewall is disabled right now. I had a NAT rule on my firewall forwarding requests from port 5060 to FreePBX; I had not locked it down to only permit requests from a specific source, so I did so, and those notices seem to have stopped.

Is it a normal configuration practice to lock down incoming requests on 5060 to only come from a specific source? I did not need to do so with 3CX, so I assumed the same configuration might hold true.


(Dave Burgess) #11

You didn’t need to, any more than you need to now, but it is best practice to do it for either system. Both systems are based on Asterisk, so not doing it for one is as bad as not doing it for the other.

As a rule, I and I alone advocate for a sensible external firewall and then locking down the FreePBX Integrated firewall. I understand that it shouldn’t be necessary, but the CISSP in me says you can’t do too much to lock your PBX down to maximize the protection.


(Adam) #12

Hi Dave,

I understand. I actually started off with having the firewall enabled, but it was causing issues with the registration of my Yealink T52S phones, though it appeared all the correct ports were opened for the registration to occur. I figured that while not ideal, having the local firewall disabled would not be harmful provided that the hardware firewall did its job. I had a limited window of time in which to do all of my testing for the system, so perhaps I will revisit that in future configurations.

Those notices have completely stopped now; is it possible that those requests could have been slamming the system so hard they could have caused that taskqueue warning?

Thanks for your assistance, I very much appreciate it.

EDIT: I contacted my VoIP Provider for assistance, and they gave me the following information:

" It seems is because you are using 100rel on your outgoing call when you support 100rel you allow PRACK with the username and password that has to be sent after a 183 Session Progress with SDP . In this case the password was not sent and we re send the 183 Session Progress to get a proper PRACK and since we did not received the response the call was not provisioned and acknowledged that is why our switch gave an error message"

There is something on the wiki about configuring PRACK (https://wiki.freepbx.org/display/DIMG/SIP+PRACK) but I can’t seem to find any similar options in either the SIP Trunk object or the SIP Trunk settings. Does this information pertain to the outbound call dropping?


(Adam) #13

Hi guys, I have updates on this issue.

I got help from a guy who knows FreePBX far, far better than me, and he was able to lock down what he thinks is the route of the issue. He used tshark to log the incoming calls, and then we looked at the contents of the packets, and found that an incorrect header was being sent. The header looked like this:

Frame 10: 972 bytes on wire (7776 bits), 972 bytes captured (7776 bits) on interface 0
Ethernet II, Src: Microsof_69:5d:04 (00:15:5d:69:5d:04), Dst: 02:cf:02:40:d1:00 (02:cf:02:40:d1:00)
Internet Protocol Version 4, Src: 192.168.40.15, Dst: 208.68.17.52
User Datagram Protocol, Src Port: 5060, Dst Port: 5060
Session Initiation Protocol (PRACK)
Request-Line: PRACK sip:7806868134@209.197.130.80:5060 SIP/2.0
Message Header
[Expert Info (Warning/Undecoded): Trailing stray characters]
Via: SIP/2.0/UDP 192.168.40.15:5060;rport;branch=z9hG4bKPj3aa9898c-52f9-4d2f-9878-74413cba334f
From: “” sip:7804788199@192.168.40.15;tag=10391aa7-0bb6-4727-87cf-69252d5a965c
To: sip:7806868134@edm.trk.tprm.ca;tag=209.197.130.80+1+4b4018+56c28ba1
Call-ID: d31f0b7e-cc8e-493f-8067-fec68cc04d04
[Generated Call-ID: d31f0b7e-cc8e-493f-8067-fec68cc04d04]
CSeq: 2979 PRACK
Route: sip:\000\000\000\000\000\000\000\000\000\000\000\000:5060;lr;r2=on;ftag=10391aa7-0bb6-4727-87cf-69252d5a965c;nat=yes
Route: sip:208.68.17.142;lr;r2=on;ftag=10391aa7-0bb6-4727-87cf-69252d5a965c;nat=yes
RAck: 486003279 2977 INVITE
Max-Forwards: 70
User-Agent: FPBX-14.0.10.3(13.22.0)

That SIP header is obviously incorrect, and in the majority of the other instances of the PRACK, it was sent back correctly.

Thus, he concluded that this is most likely a bug within FreePBX. It is worth noting that I was using a pjsip trunk; he recommended I move to sip instead, as it is more mature and unlikely to have this issue. I will be doing so, and then monitoring over a few days to see if the issue goes away.

Is this a known issue within FreePBX? Is there a setting I can set within the pjsip trunk that will resolve this issue?

Kind regards!


#14

Not tested, but try putting or adding
100rel=no
to /etc/asterisk/pjsip_custom.conf

and restarting Asterisk.

Of course, this turns off PRACK, so if a 180 Ringing or 183 Progress packet gets lost, the caller will hear silence until the call is answered. If the connection to the provider is solid, this shouldn’t be an issue. chan_sip never supported 100rel at all.

You can easily check. At the Asterisk console, type
pjsip set logger on
make a test call and confirm that the PRACKs are gone.


(Adam) #15

Hi Stewart,

Thanks for the tip. I will try it in a future PJSIP trunk. For the moment, changing to SIP seems to have done the trick, and the issue can be closed.

Thanks!


(system) closed #16

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