Exceptionally long voice queue length queuing to Local

[marcin]

vicibox installation
VERSION: 2.14-714a
BUILD: 190628-1511
Asterisk 11.25.1-vici
Timer card Amfeltec VoiceSync (pcie) installed.
Server is rebooted every night, pv6 disabled, unused ram is released drop_caches from crotab every minute.
And there is no external attacks on the server.

From time to time I see "Exceptionally long voice queue length queuing" errors in asterisk logs. If there is just a fief during a day there is no issue, but when I see lots of these the asterisk stops responding, not crashing, but not accepting any more sip messages.

In last 2 days I have noticed new WARNING in asterisk logs :
channel.c: Unable to write to alert pipe on Local/58600072@default-0000afdc;1 (qlen = 90): Resource temporarily unavailable!
By it self this message is harmless, however Local/58600072 is an extension of quiet monitor-only extensions for meetme rooms: Asterisk 1.8 workaround
and 58600072 was not the only one listed in logs with same warning I can see 4 other quiet monitor extensions.
The WARNINGS continued overnight all the way until crontab rebooted the server.
I believe that the 5 monitoring channels did not hangup and between Unable to write to alert pipe WARNINGS I've seen a lot of Exceptionally long voice queue length queuing warnings referring to same channels despite the fact that there was no agents logged on to the server at that time (4 AM EST)

this is a small part of logs:
[Aug 14 04:01:02] WARNING[17738][C-0000b473] channel.c: Unable to write to alert pipe on Local/58600081@default-0000b09d;1 (qlen = 95): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[15231][C-0000b3a9] channel.c: Unable to write to alert pipe on Local/58600072@default-0000afdc;1 (qlen = 84): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[13603][C-0000b322] channel.c: Unable to write to alert pipe on Local/58600086@default-0000af5f;1 (qlen = 64): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[15809][C-0000b3db] channel.c: Exceptionally long voice queue length queuing to Local/58600080@default-0000b00c;1
[Aug 14 04:01:02] WARNING[15809][C-0000b3db] channel.c: Unable to write to alert pipe on Local/58600080@default-0000b00c;1 (qlen = 96): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[17841][C-0000b482] channel.c: Unable to write to alert pipe on Local/58600071@default-0000b0ab;1 (qlen = 73): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[17738][C-0000b473] channel.c: Exceptionally long voice queue length queuing to Local/58600081@default-0000b09d;1
[Aug 14 04:01:02] WARNING[17738][C-0000b473] channel.c: Unable to write to alert pipe on Local/58600081@default-0000b09d;1 (qlen = 96): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[15231][C-0000b3a9] channel.c: Unable to write to alert pipe on Local/58600072@default-0000afdc;1 (qlen = 85): Resource temporarily unavailable!
[Aug 14 04:01:02] WARNING[13603][C-0000b322] channel.c: Unable to write to alert pipe on Local/58600086@default-0000af5f;1 (qlen = 65): Resource temporarily unavailable!

I understand that "Exceptionally long voice queue length " may be caused by slow internet connection or a timing issue.
The timing should not be a problem here since there is a Amfeltec card installed and dahdi is loading the driver.
As to the internet connection the server is on 100 Mbps fiber connection in a colo facility, but one of the agents location may be on little slower connection.
Asterisk shows 300-400 ms status to the extensions in question, but there is no much of UNREACHABLE NOTICEs corresponding to WARNINGS.

I guess my questions are:
Since the asterisk version is 11 not 1.8 should managers use other then 586000XX to monitor the calls?
Why are these channels do not get hangup?
Is there a way to hangup/kill these channels?
I can write a simple script monitoring the asterisk logs and "kill" the conference when 2-3 "Exceptionally long voice queue length" Waring appears referring to same conference. It would kick the agent off, but prevent the asterisk from not responding and bring the entire operation down.
Anyone have any other ideas or experience with same issue and possible workaround/fix.

[ambiorixg12]

You get this message when your system is out of resources

[Aug 14 04:01:02] WARNING[15231][C-0000b3a9] channel.c: Unable to write to alert pipe on Local/58600072@default-0000afdc;1 (qlen = 84): Resource temporarily unavailable!

check your CPU usage with the top command

[williamconley]

You get this message when your system is out of resources

[Aug 14 04:01:02] WARNING[15231][C-0000b3a9] channel.c: Unable to write to alert pipe on Local/58600072@default-0000afdc;1 (qlen = 84): Resource temporarily unavailable!

check your CPU usage with the top command

Excellent post.

Also: Check system logs. It may not be memory specifically. There are all sorts of artificial barrier in place in linux to protect you from yourself. Many of these need to be removed for a Vicidial system, but this is based entirely on usage of the individual. Luckily, most of these barriers generate an error somewhere in the system logs to tell you Which barrier is in the way this time.

[marcin]

I have checked the logs again and I found out that WARNING "Exceptionally long voice queue length queuing" started appearing exactly when a channel was hanged up. In other words the "Exceptionally long voice queue length queuing" WARNING was caused by hangup of a channel (well sort of). Since I did not find agent logging off after this channel was hangup I can only assume that the channel was the last one that left the conference but the conference did not get terminated.

[Aug 13 20:56:21] VERBOSE[13604][C-0000b322] pbx.c: [Aug 13 20:56:21] -- Executing [8309@default:4] Hangup("Local/58600086@default-0000af5f;1", "") in new stack
[Aug 13 20:56:21] VERBOSE[13604][C-0000b322] pbx.c: [Aug 13 20:56:21] == Spawn extension (default, 8309, 4) exited non-zero on 'Local/58600086@default-0000af5f;1'
[Aug 13 20:56:21] VERBOSE[13604][C-0000b322] pbx.c: [Aug 13 20:56:21] -- Executing [h@default:1] AGI("Local/58600086@default-0000af5f;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
[Aug 13 20:56:21] VERBOSE[13604][C-0000b322] res_agi.c: [Aug 13 20:56:21] -- <Local/58600086@default-0000af5f;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Aug 13 20:56:22] VERBOSE[25380] manager.c: [Aug 13 20:56:22] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:23] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:24] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:25] VERBOSE[25386] manager.c: [Aug 13 20:56:25] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:26] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:27] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:28] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:28] VERBOSE[25391] manager.c: [Aug 13 20:56:28] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:29] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:31] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:31] VERBOSE[25395] manager.c: [Aug 13 20:56:31] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:32] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:33] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:34] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:35] VERBOSE[25399] manager.c: [Aug 13 20:56:35] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:36] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:37] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:38] VERBOSE[25404] manager.c: [Aug 13 20:56:38] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:38] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:40] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:41] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:41] VERBOSE[25408] manager.c: [Aug 13 20:56:41] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:42] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:43] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:44] VERBOSE[25412] manager.c: [Aug 13 20:56:44] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:45] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:46] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:47] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:47] VERBOSE[25420] manager.c: [Aug 13 20:56:47] == Manager 'updatecron' logged on from 127.0.0.1
[Aug 13 20:56:49] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1
[Aug 13 20:56:50] WARNING[13603][C-0000b322] channel.c: Exceptionally long voice queue length queuing to Local/58600086@default-0000af5f;1



As you can see channel Local/58600086@default-0000af5f;1 should be Hanged up but it remain open and generated flood of messages
Also it looks as this was an monitoring channel, these is a cut from logs about 1 hour earlier:





[Aug 13 19:56:21] VERBOSE[13603][C-0000b322] pbx.c: [Aug 13 19:56:21] -- Executing [58600086@default:1] MeetMe("Local/58600086@default-0000af5f;2", "8600
086,Fmq") in new stack
[Aug 13 19:56:21] VERBOSE[13602][C-0000b322] pbx.c: [Aug 13 19:56:21] > Channel Local/58600086@default-0000af5f;1 was answered
[Aug 13 19:56:21] VERBOSE[13604][C-0000b322] pbx.c: [Aug 13 19:56:21] -- Executing [8309@default:1] Answer("Local/58600086@default-0000af5f;1", "") in ne
w stack
[Aug 13 19:56:21] VERBOSE[13604][C-0000b322] pbx.c: [Aug 13 19:56:21] -- Executing [8309@default:2] Monitor("Local/58600086@default-0000af5f;1", "wav,201
90814-052620_9402057976") in new stack
[Aug 13 19:56:21] VERBOSE[13604][C-0000b322] pbx.c: [Aug 13 19:56:21] -- Executing [8309@default:3] Wait("Local/58600086@default-0000af5f;1", "3600") in
new stack


And per timestamp it appears that it was hanged up by a timeout of 3600 sec.

[williamconley]

unused ram is released drop_caches from crotab every minute

If this is the DB server: Do not do this. you're not "freeing up memory", you are breaking a feature of mysql. MySQL will leave used queries in memory, but mark the memory available. However, if the exact same query is requested without any changes to those records, the query can be pulled from memory ... drastically reducing the time needed to recover the data and eliminating the disk read entirely. Your "cleanup" then causes unnecessary drive usage and extra cpu usage, plus what may happen when there is a collision of "i need that" overlapping "delete that" which ordinarily would never happen (or so infrequently that it would qualify as never, in theory).

Based on your description of the "special things" you've done to your system, I am presently of the opinion that one of those special things (or a combination of them) is the root of your issue.

1) Duplicate the problem if you can. During a test scenario. Once you can duplicate it:
2) Try it on a freshly installed system without your special changes. If the problem does not happen ...
3) Put your special changes in and test again. If it happens you found your problem is your special changes. Now you need to find out which one.

[marcin]

An update:
I have been trying for weeks to resolve "Exceptionally long voice queue length queuing" error.
ngrep/tcpdump script monitoring any potential attacks or malformed sip messages did not show any abnormalities.
Script monitoring internet connection hardly missed a bit.
Reinstalling all software, hardware replacement did not help.
Dahdi timer card introduction and replacement also did not correct the issue.
Countless hours of searching for possible cause and/or solution was fruitless. Digium/asterisk did not responded to any of many similar issues.
Suggested kernel parameters; nopti nospectre_v2 acpi=off noapic, asterisk modules disabling and plenty other attempts did not corrected nor helped.
Some suggestions pointed in to internet connection issues, so I started to look in to my own iptables firewall setup.
Finally after all this time and many sleepless nights:
1 (ONE) port from rtp range was used for something else. I did it as a security precaution and bind sip port to 15xxx what is just above the middle of default asterisk rtp range. After little googling I found out that the way the asterisk assign rtp port to a channel ;it starts at the middle of the configured rtp range, continues to "scan" ports to the highest, then from bottom back to the middle. Apparently asterisk's way of verification if port is available is simply looking in to its own usage.
What was happening: asterisk assign 15xxx (my sip signaling port) to a channel and the audio was expected to flow. When this did not happened then the long voice queue error was generated, channel dropped and according to asterisk port was available to be used again, therefor same port was assign to next call and the crazy loop continued until asterisk was not able to process calls any more and crashed.
Even though the providers ware whitelisted in firewall they often redirect rtp to other ip addresses that ware blocked on my sip signaling port.Even if the port was not used,but block only same thing would have happened
The solution:
I have moved the rtp port range from 10000-20000 to 16000-26000
The advice:
Make sure your entire range of rtp ports is open in firewall, and none of the ports are used by any other application.
Math:
Say your rtp ports are 10000-20000 and port 15200 is blocked or used by other application, 40 agents (80 ports) and any call over 60 outbound calls will hit 15200 and generate the error.
Summary:
I am an idiot, I should be able to spot this within days if not hours, definitely not weeks, but this is what happens if one assumes too much.