| Summary: | ASTERISK-16258: [patch] Brief lagginess on IAX2 channels is fatal | ||
| Reporter: | John Covert (jcovert) | Labels: | |
| Date Opened: | 2010-06-17 10:32:37 | Date Closed: | 2015-03-14 17:41:40 |
| Priority: | Major | Regression? | No |
| Status: | Closed/Complete | Components: | Channels/chan_iax2 |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ( 0) backout-channel.c.patch ( 1) log-2010-06-22.txt.aes ( 2) log-2010-06-30.txt.aes | |
| Description: | The problem reported in issue ASTERISK-14558 and ASTERISK-14834 continues: [Jun 17 09:55:14] WARNING[15579]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/x38-9660 [Jun 17 09:57:54] WARNING[15579]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/x38-9660 [Jun 17 09:57:54] WARNING[15579]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/x38-9660 [Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer: Peer 'x29' is now UNREACHABLE! Time: 2 [Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer: Peer 'jrclaptop' is now UNREACHABLE! Time: 4 [Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer: Peer 'x38' is now UNREACHABLE! Time: 136 [Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/x38-9660 [Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/x38-9660 [Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/x38-9660 -- Hungup 'IAX2/x38-9660' == Spawn extension (dialstation, 38, 1) exited non-zero on 'SIP/x28-0000048b' [Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer 'x29' is now REACHABLE! Time: 2 [Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer 'jrclaptop' is now REACHABLE! Time: 4 [Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer 'x38' is now REACHABLE! Time: 137 This tends to reproduce for me only on transatlantic calls. /john | ||
| Comments: | By: Leif Madsen (lmadsen) 2010-06-17 13:27:02 Is there any additional logging or information you can provide? Since this seems to be quite the sticky issue, more information is probably better than less :) By: John Covert (jcovert) 2010-06-22 21:40:04 OK, I've uploaded an encrypted log. Key is available by phone: iax2/john@iax.covert.org or sip:covert@covert.org. openssl aes-128-cbc -d -salt -in log-2010-06-22.txt.aes I placed an IAX2 call to an asterisk server on the west coast. Soon audio started dropping, and other bad things happened. x29 is a local iaxy -- communications to it went wonky. x38 is an IAX2 asterisk peer across the Atlantic. Things for it went weird, too. Eventually, the IAX2 call dropped. This is easy to reproduce on any slightly laggy circuit. In fact, you could probably reproduce it by calling the same IAX2 address I used, taken from the logs. It's an audio monitor next to an old step-by-step switch. For fun, while you're listening to the monitor, place a call from another line to x5555. /john I will gladly do additional logging By: John Covert (jcovert) 2010-06-30 08:01:03 I have uploaded another log. Please call me for the password as indicated above. Decode with aes-128-cbc -d -salt -in log-2010-06-30.txt.aes As stated before, I will gladly instrument the code as instructed and do additional logging. /john By: Paul Belanger (pabelanger) 2010-06-30 08:05:29 Rather then encrypting your logs, we can convert this issue to private if they contain sensitive data. By: John Covert (jcovert) 2010-06-30 08:34:56 I would hope that some of the other people who have reported this problem would possibly be able to provide additional information; that won't happen if we make this private. By: John Covert (jcovert) 2010-07-05 14:53:47 I am beginning to think this is a performance problem in queue handling which is more likely to affect a machine with a slower processor. [BACKING AWAY FROM THIS... SEE NEXT ENTRY.] I did not have quite the same the problem when I was running asterisk-1.6.0.3. I have two PowerPC laptops with Asterisk. My main PBX runs on a 550 MHz original Titanium. I also run asterisk on another Alumninum Powerbook (1.33 GHz). Both are running identical kernels, and both are now running 1.6.2.9. The faster machine does not have this problem at all. I downgraded the slower machine to 1.6.0.3 and no longer see the queue length messages. Instead, what I see on 1.6.0.3 is: [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 11, ts=20012, seqno=6) [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 2, ts=21008, seqno=7) [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 11, ts=30017, seqno=8) [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 11, ts=40022, seqno=9) [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 2, ts=42012, seqno=10) [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 12, ts=10005, seqno=11) [Jul 5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type = 6, subclass = 12, ts=20004, seqno=12) The following may or may not be related. I see it on the slower machine but not on the faster one. asterisk*CLI> iax2 reload [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set peer->pokefreqnotok to 200 [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set peer->pokefreqnotok to 5000 [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set peer->pokefreqnotok to 5000 [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set peer->pokefreqnotok to 5000 [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool [Jul 5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init: trying to reset empty pool By: John Covert (jcovert) 2010-07-05 16:32:20 AHAH! No problem if the originating caller is ulaw. However, transcoding from G.722 on a SIP client originating the call to an outgoing IAX2 call seems to make it happen. But apparently only if that's the only call. Right now: Channel Peer Username ID (Lo/Rem) Seq (Tx/Rx) Lag Jitter JitBuf Format FirstMsg LastMsg IAX2/64.25.152.29:45 64.25.152.29 cnetguest 00016/10470 00043/00043 00118ms -0001ms 0000ms ulaw Tx:NEW Rx:ACK IAX2/jrclaptop-178 72.93.205.51 jrclaptop 00178/00219 00204/00222 00040ms -0001ms 0000ms ulaw Rx:NEW Tx:ACK IAX2/174.136.97.11:4 174.136.97.11 guest 07237/04376 00093/00094 00040ms -0001ms 0000ms g722 Tx:NEW Rx:ACK IAX2/64.25.152.29:45 64.25.152.29 cnetguest 07653/08446 00198/00189 00142ms -0001ms 0000ms ulaw Tx:NEW Tx:ACK and asterisk*CLI> sip show channels Peer User/ANR Call ID Format Hold Last Message Expiry 192.168.0.41 x37 3c2bdca2d12f-32 0x1000 (g722) No Rx: ACK 192.168.0.16 x28 3c5d5e84bad9-26 0x1000 (g722) No Rx: ACK No 10 active SIP dialogs (non-call removed) We are now having NO problem at all. We have one IAX-IAX call (ulaw both sides) and we have two SIP to IAX calls (originator G722 transcoding to ulaw in both cases). /john By: John Covert (jcovert) 2010-07-12 13:22:45 I upgraded my FiOS from 20/5 to 25/25 and the problem is REDUCED but not gone. Calling the same test location, I can no longer get the "Exceptionally long voice queue length" messages, but with a single call there is still very poor voice quality. Adding a second call clears up the voice quality (just as it seemed to clear up the whole problem when my upload was only 5Mbps). /john By: John Covert (jcovert) 2010-07-13 15:23:11 With a fairly heavy additional (non-asterisk) upload, I can still get: -- Executing [13777777@cnetlookup:13] Dial("SIP/x28-00000207", "IAX2/cnetguest@weco355a.dyndns.org/13777777,120") in new stack -- Called cnetguest@weco355a.dyndns.org/13777777 -- Call accepted by 64.25.152.29 (format ulaw) -- Format for call is ulaw -- IAX2/64.25.152.29:4569-8938 answered SIP/x28-00000207 [Jul 13 16:19:54] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:19:54] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:19:54] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:19:54] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:20:00] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:20:00] NOTICE[21633]: chan_iax2.c:10424 socket_process: Peer 'x38' is now TOO LAGGED (2256 ms)! [Jul 13 16:20:00] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:20:12] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:20:12] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:20:12] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 [Jul 13 16:20:12] WARNING[21633]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/64.25.152.29:4569-8938 and G.722 transcoding does not seem to be required, but it does make it worse. Two calls still seems to make it better. By: Darik Horn (dajhorn) 2010-07-14 13:56:58 I was affected by this bug after an upgrade from Asterisk 1.6.2.0 on Ubuntu Karmic to Asterisk 1.6.2.5 on Ubuntu Lucid. On my PBX, it resulted in voice prompts being cut-off and the "follow me" feature being unable to connect with external POTS numbers. My kludge was to replace IAX trunking with SIP trunking wherever possible. My PBX became rock solid again after applying this change. By: Ravelomanantsoa Hoby (hoby) 2010-07-18 09:27:20 I'm facing this type of bug, mine is like ASTERISK-1543609. Calls arrive in Queue and when connecting to Agent displays [2010-07-18 17:11:09] WARNING[5393]: channel.c:952 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8552@AGENT-eb6c,1 [2010-07-18 17:11:22] WARNING[5525]: channel.c:952 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8528@AGENT-a90b,1 [2010-07-18 17:12:22] WARNING[6264]: channel.c:952 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8533@AGENT-d608,1 Those warnings seems to happen when agent can not hear the caller from queue until some seconds (up to 10s) after he pick up the call, and on the other party the caller in the queue have the musiconhold blanked out for some second. We used Asterisk 1.4.21.2 for many months without this delay and recently this sort of delay appears, we have tried up to run Asterisk 1.4.21.2 with few calls and still has those symptom. we decide to upgrade to 1.4.33.1 and the symptom persist with displaying "exceptionally long voice queue" this also happen with 1.4.34rc2. Our asterisk run on bi-quad core 3ghz with 24G of memory. I tried to fix the issue relaying on the patch ASTERISK-1543609 but when this is applied, agent get phone's ringing and when they pickup hear no voice and meanwhile the caller from queue still hear music on hold. Should i open new issue or this relate to this issue? By: Leif Madsen (lmadsen) 2010-07-20 10:52:11 hoby: it's probably related to this issue By: John Covert (jcovert) 2010-07-20 11:08:00 I acquired a new client yesterday who has informed me that one of their work items is to replace the IAX trunking between locations with SIP trunking, specifically because IAX sound quality has recently deteriorated. By: Ravelomanantsoa Hoby (hoby) 2010-07-26 07:00:30 I found that when asterisk have send the manager event AgentConnect the agent and the caller can hear to each other. Before that, agent pickup the phone but hear no voice for a while. Then i looked up into the app_queue.c; i see that asterisk log into queue_log before sending the event AgentConnect and just after that bridge the two channels. So, i suspect logging delay, i decide then to replace the queue_log file by a null file: just do ln -s /dev/null /var/log/asterisk/queue_log When done, things seems goes fine: - no more warning exceptionally long voice - when agent pick up the call he directly hear caller voice So, mine looks to be relative to disk performance. Many months before we doesn't have this issue with same asterisk and configuration so this can explain the disk performance when data grows up. Is it possible to move forward bridging channel before logging into queue_log inside app_queue.c ? After a 2 hour of testing these warning reapears :-( IF I REUSE QUEUELOG By: Leif Madsen (lmadsen) 2010-07-26 13:59:22 hoby: so are you saying if you remove the logging (or rather send it to null) that the problem goes away? Perhaps the code just needs to be rearranged to move the logging to after the AgentConnect stuff? By: Ravelomanantsoa Hoby (hoby) 2010-08-10 05:57:15 lmadsen: exact, when i send logging to null agent hear directly the caller. I did some rearrangement for the logging code. I moved logging AgentConnect after bridging channels By: artlink (artlink) 2010-12-20 03:39:32.000-0600 Patch 0015609 not allow the execution of the transfer atxfer asterisk manager api version1.6.2.14.rc.1. When the transfer is made not to hear. However, this error occurs quite often when performing atxfer. [Dec 1917 8:03:08 p.m.] WARNING [27650] channel.c: Exceptionally long queue length queuing voice is Local/1205 * 1036664_1_6749.0_815335973_1_2010-12-17_20: 00:14 @ Atxfer-b86b; 1 By: John Covert (jcovert) 2010-12-20 06:05:37.000-0600 This past week I had some more experience with this problem: Call was placed from the asterisk instance in Germany to my instance in the U.S., and the codec choice the whole way ended up being G.711, because it was answered in the U.S. on a Cisco ATA186. We talked at length with no problems. I then did a blind xfer to a Snom 300, which had the G.722 codec available, and chose to use it and transcode. Due to the slight extra overhead of transcoding, the lagginess occurred and conversation became difficult. A blind xfer back to a 2500 set on an ATA186 restored the call quality to normal. and now I see that this is not new information, but rather the same as reported in (0124236). I was reading the code some months ago, and noticed that the code which handles the queue and checks the queue length has a scaling problem: since the queue is singly-linked and there is no count of entries maintained, the queue length is checked by traversing the queue. As more entries are placed on the queue, this traversal time gets longer, exacerbating the problem. Removal from the queue also requires traversal. Since this is a FIFO queue, for efficiency it should be doubly linked, with both a head and tail pointer, in order to allow insertion at one end and removal at the other without requiring traversal. This does not seem to explain why putting up two calls reduces the problem. /john By: capouch (capouch) 2010-12-27 21:31:23.000-0600 I just built 1.8.8.1 for use on my openWRT (trunk, reasonably recent) instance. This bug now crashes the system hard, requiring a reboot without fail. Once the bug has begun to show up (audio begins to break up) the CLI dies, all other open shells on the system go unresponsive, and after 45-90 seconds of intense activity on the Ethernet (the only thing I can do is watch the LEDs) memory is exhausted (I assume) and I get a reboot. I symlinked /var/log/asterisk/messages to /dev/null; it slowed down the process some but didn't stop it. By: John Covert (jcovert) 2010-12-29 20:58:16.000-0600 I have a solid reproducer on this now under 1.8.1.1 Everything is on the local LAN. Device at x33 is a Cisco ATA186. At the CLI, type: asterisk*CLI> originate sip/x33 application dial IAX2/guest@iax.covert.org/ringnoanswer Answer the phone connected to the Cisco ATA186. The Dial command executes, and terminates on the same machine at:: exten => ringnoanswer,1,Progress() exten => ringnoanswer,n,Noop(${CALLERID(all)}) exten => ringnoanswer,n,Playtones(440+495/2000,0/4000) exten => ringnoanswer,n,Wait(120) ; Implement a Ring-no-Answer exten => ringnoanswer,n,Hangup The following appears: -- Launching dial(IAX2/guest@iax.covert.org/ringnoanswer) on SIP/x33-0000010e -- Called guest@iax.covert.org/ringnoanswer -- Accepting UNAUTHENTICATED call from 192.168.0.100: > requested format = ulaw, > requested prefs = (ulaw|alaw|g726|gsm), > actual format = ulaw, > host prefs = (ulaw|alaw|g726|gsm), > priority = caller -- Call accepted by 192.168.0.100 (format ulaw) -- Format for call is ulaw -- Executing [ringnoanswer@sip:1] Progress("IAX2/192.168.0.100:4569-2400", "") in new stack -- Executing [ringnoanswer@sip:2] NoOp("IAX2/192.168.0.100:4569-2400", ""Cisco 33" <33>") in new stack -- Executing [ringnoanswer@sip:3] PlayTones("IAX2/192.168.0.100:4569-2400", "440+495/2000,0/4000") in new stack -- Executing [ringnoanswer@sip:4] Wait("IAX2/192.168.0.100:4569-2400", "120") in new stack -- IAX2/192.168.0.100:4569-13524 is making progress passing it to SIP/x33-0000010e [Dec 29 21:43:35] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-13524 -- Hungup 'IAX2/192.168.0.100:4569-13524' [Dec 29 21:43:51] WARNING[22843]: chan_iax2.c:1123 iax_error_output: Information element length exceeds message size [Dec 29 21:43:51] WARNING[22843]: chan_iax2.c:9901 socket_process: Undecodable frame received from '192.168.0.4' == Spawn extension (sip, ringnoanswer, 4) exited non-zero on 'IAX2/192.168.0.100:4569-2400' -- Hungup 'IAX2/192.168.0.100:4569-2400' Note that while all of this was going on, the rest of the IAX world was getting screwed up. Here's a remote IAX peer that was inactive, except for ping/pokes: [Dec 29 21:43:54] NOTICE[22843]: chan_iax2.c:11867 __iax2_poke_noanswer: Peer 'x38' is now UNREACHABLE! Time: 234 [Dec 29 21:43:59] NOTICE[22843]: chan_iax2.c:10802 socket_process: Peer 'x38' is now REACHABLE! Time: 133 Now that I have this easy reproducer, how do we work on actually solving this problem? It would be great to restore credibility to the IAX channel. /john By: John Covert (jcovert) 2010-12-29 21:25:26.000-0600 In case you don't have a Cisco ATA 186 handy, a Polycom 330 will do just fine. x26 is a Polycom on the local LAN as well: asterisk*CLI> originate sip/x26 application dial IAX2/guest@iax.covert.org/ringnoanswer -- Launching dial(IAX2/guest@iax.covert.org/ringnoanswer) on SIP/x26-0000010f -- Called guest@iax.covert.org/ringnoanswer -- Accepting UNAUTHENTICATED call from 192.168.0.100: > requested format = ulaw, > requested prefs = (ulaw|alaw|g726|gsm), > actual format = ulaw, > host prefs = (ulaw|alaw|g726|gsm), > priority = caller -- Call accepted by 192.168.0.100 (format ulaw) -- Format for call is ulaw -- Executing [ringnoanswer@sip:1] Progress("IAX2/192.168.0.100:4569-14367", "") in new stack -- Executing [ringnoanswer@sip:2] NoOp("IAX2/192.168.0.100:4569-14367", ""Cisco 26" <26>") in new stack -- Executing [ringnoanswer@sip:3] PlayTones("IAX2/192.168.0.100:4569-14367", "440+495/2000,0/4000") in new stack -- IAX2/192.168.0.100:4569-9274 is making progress passing it to SIP/x26-0000010f -- Executing [ringnoanswer@sip:4] Wait("IAX2/192.168.0.100:4569-14367", "120") in new stack [Dec 29 22:21:43] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:21:43] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:21:44] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:21:51] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:21:56] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:21:57] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:21:57] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-14367 [Dec 29 22:22:06] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:22:06] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-14367 [Dec 29 22:22:07] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:22:08] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:22:14] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 [Dec 29 22:22:15] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-9274 -- Hungup 'IAX2/192.168.0.100:4569-9274' [Dec 29 22:22:59] WARNING[22843]: channel.c:1399 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-14367 == Spawn extension (sip, ringnoanswer, 4) exited non-zero on 'IAX2/192.168.0.100:4569-14367' -- Hungup 'IAX2/192.168.0.100:4569-14367' [Dec 29 22:22:59] NOTICE[22843]: chan_iax2.c:11867 __iax2_poke_noanswer: Peer 'x38' is now UNREACHABLE! Time: 300 [Dec 29 22:23:01] NOTICE[22843]: chan_iax2.c:11867 __iax2_poke_noanswer: Peer 'jrclaptop' is now UNREACHABLE! Time: 4 [Dec 29 22:23:04] NOTICE[22843]: chan_iax2.c:10802 socket_process: Peer 'x38' is now REACHABLE! Time: 133 [Dec 29 22:23:06] NOTICE[22843]: chan_iax2.c:10802 socket_process: Peer 'jrclaptop' is now REACHABLE! Time: 4 Note that this time both the remote x38 IAX peer as well as a LOCAL IAX peer (jrclaptop) went unreachable during the test. /john By: John Covert (jcovert) 2011-01-11 20:31:31.000-0600 As noted, issue ASTERISK-17143 appears related. I have uploaded debugger output from several hangs there. By: John Covert (jcovert) 2011-01-18 22:25:08.000-0600 The problem persists in 1.8.2.1: -- Executing [c-14849601@dialcnet:4] Dial("SIP/x37-00000010", "IAX2/cnet-guest@franksmicro.dyndns.org/14849601,120") in new stack -- Called cnet-guest@franksmicro.dyndns.org/14849601 -- Call accepted by 98.118.147.150 (format ulaw) -- Format for call is ulaw -- IAX2/98.118.147.150:4569-964 answered SIP/x37-00000010 [Jan 18 23:18:42] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'jsolathome' is now UNREACHABLE! Time: 36 [Jan 18 23:18:52] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'x38' is now UNREACHABLE! Time: 133 [Jan 18 23:19:02] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'jrclaptop' is now UNREACHABLE! Time: 69 [Jan 18 23:19:04] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:04] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:04] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 -- Registered IAX2 'jsolathome' (AUTHENTICATED) at 75.9.135.199:4569 [Jan 18 23:19:12] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:21] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:21] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 -- Registered IAX2 'x29' (AUTHENTICATED) at 192.168.0.17:4569 [Jan 18 23:19:23] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:23] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:23] WARNING[939]: chan_iax2.c:1123 iax_error_output: Information element length exceeds message size [Jan 18 23:19:23] WARNING[939]: chan_iax2.c:9904 socket_process: Undecodable frame received from '79.240.198.57' -- Registered IAX2 'jrclaptop' (AUTHENTICATED) at 192.168.0.4:4569 [Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:47] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer 'x38' is now REACHABLE! Time: 496 [Jan 18 23:19:47] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'jrclaptop' is now UNREACHABLE! Time: 10 [Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:10] NOTICE[939]: chan_iax2.c:10811 socket_process: Peer 'x29' is now TOO LAGGED (3910 ms)! [Jan 18 23:20:10] NOTICE[939]: chan_iax2.c:10811 socket_process: Peer 'jsolathome' is now TOO LAGGED (2268 ms)! [Jan 18 23:20:11] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer 'x29' is now REACHABLE! Time: 526 [Jan 18 23:20:11] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'x38' is now UNREACHABLE! Time: 496 [Jan 18 23:20:12] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer 'jrclaptop' is now REACHABLE! Time: 114 [Jan 18 23:20:12] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:15] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:15] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:16] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer 'x38' is now REACHABLE! Time: 225 -- Registered IAX2 'jsolathome' (AUTHENTICATED) at 75.9.135.199:4569 [Jan 18 23:20:22] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'jsolathome' is now UNREACHABLE! Time: 2268 [Jan 18 23:20:36] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'jrclaptop' is now UNREACHABLE! Time: 114 [Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:40] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer: Peer 'x38' is now UNREACHABLE! Time: 225 [Jan 18 23:20:41] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer 'jrclaptop' is now REACHABLE! Time: 6 [Jan 18 23:20:55] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:55] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:55] WARNING[939]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/98.118.147.150:4569-964 [Jan 18 23:20:56] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer 'x38' is now REACHABLE! Time: 742 -- Hungup 'IAX2/98.118.147.150:4569-964' == Spawn extension (dialcnet, c-14849601, 4) exited non-zero on 'SIP/x37-00000010' By: John Covert (jcovert) 2011-01-26 16:36:33.000-0600 Argggh. IAX just really doesn't work any more. Period. [Jan 26 17:33:22] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:22] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:22] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:22] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:27] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:27] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:29] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 [Jan 26 17:33:29] WARNING[18206]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/66.54.140.46:4569-10868 By: Sean Bright (seanbright) 2011-01-27 09:17:46.000-0600 Is this still 1.6.2.something on both sides? By: John Covert (jcovert) 2011-01-27 10:18:47.000-0600 No. This is 1.8.2.1. It can be reproduced in a single system. See the last few notes, especially (0130036). /john By: Sean Bright (seanbright) 2011-01-27 10:56:13.000-0600 Can you post your IAX configuration you used in your test in note 0130036? I want to lab it up. You can mask out the private bits, obviously. By: John Covert (jcovert) 2011-01-27 11:09:21.000-0600 asterisk-1.8.2.1 root# mv configs/iax.conf.sample /etc/asterisk/iax.conf extensions.conf: [default] exten => ringnoanswer,1,Progress() exten => ringnoanswer,n,Noop(${CALLERID(all)}) exten => ringnoanswer,n,Playtones(440+495/2000,0/4000) exten => ringnoanswer,n,Wait(120) ; Implement a Ring-no-Answer exten => ringnoanswer,n,Macro(fastbusy,busy) ; Time out to busy asterisk*CLI> originate sip/x33 application dial IAX2/guest@iax.covert.org/ringnoanswer -- Launching dial(IAX2/guest@iax.covert.org/ringnoanswer) on SIP/x33-00000000 -- Accepting UNAUTHENTICATED call from 192.168.0.100: > requested format = gsm, > requested prefs = (), > actual format = gsm, > host prefs = (), > priority = mine -- Call accepted by 192.168.0.100 (format gsm) -- Called guest@iax.covert.org/ringnoanswer -- Executing [ringnoanswer@default:1] Progress("IAX2/192.168.0.100:4569-2690", "") in new stack -- Executing [ringnoanswer@default:2] NoOp("IAX2/192.168.0.100:4569-2690", ""Guest IAX User" <>") in new stack -- Executing [ringnoanswer@default:3] PlayTones("IAX2/192.168.0.100:4569-2690", "440+495/2000,0/4000") in new stack -- Executing [ringnoanswer@default:4] Wait("IAX2/192.168.0.100:4569-2690", "120") in new stack -- Format for call is gsm -- IAX2/192.168.0.100:4569-3232 is making progress passing it to SIP/x33-00000000 [Jan 27 12:03:38] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:03:56] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:03:57] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-2690 [Jan 27 12:03:57] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-2690 [Jan 27 12:04:05] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:04:06] WARNING[26159]: chan_iax2.c:1123 iax_error_output: Information element length exceeds message size [Jan 27 12:04:06] WARNING[26159]: chan_iax2.c:9904 socket_process: Undecodable frame received from '87.157.219.98' [Jan 27 12:04:17] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:04:18] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-2690 [Jan 27 12:04:23] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:04:24] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:04:33] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:04:37] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 [Jan 27 12:04:42] WARNING[26159]: channel.c:1426 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/192.168.0.100:4569-3232 By: Sean Bright (seanbright) 2011-01-27 11:15:34.000-0600 So just the virgin iax.conf.sample, then. Check. By: Sean Bright (seanbright) 2011-01-27 15:36:06.000-0600 Not disputing your findings, but with the latest from the 1.8 branch I am not able to replicate in my environment: -- Launching dial(IAX2/guest@10.27.0.29/ringnoanswer) on SIP/meh-00000001 -- Called guest@10.27.0.29/ringnoanswer -- Accepting UNAUTHENTICATED call from 10.27.0.29: > requested format = gsm, > requested prefs = (), > actual format = gsm, > host prefs = (), > priority = mine -- Call accepted by 10.27.0.29 (format gsm) -- Format for call is gsm -- Executing [ringnoanswer@default:1] Progress("IAX2/10.27.0.29:4569-1426", "") in new stack -- Executing [ringnoanswer@default:2] NoOp("IAX2/10.27.0.29:4569-1426", ""Guest IAX User" <>") in new stack -- Executing [ringnoanswer@default:3] PlayTones("IAX2/10.27.0.29:4569-1426", "440+495/2000,0/4000") in new stack -- IAX2/10.27.0.29:4569-925 is making progress passing it to SIP/meh-00000001 -- Executing [ringnoanswer@default:4] Wait("IAX2/10.27.0.29:4569-1426", "120") in new stack -- Executing [ringnoanswer@default:5] Hangup("IAX2/10.27.0.29:4569-1426", "") in new stack == Spawn extension (default, ringnoanswer, 5) exited non-zero on 'IAX2/10.27.0.29:4569-1426' -- Hungup 'IAX2/10.27.0.29:4569-1426' -- Hungup 'IAX2/10.27.0.29:4569-925' -- No one is available to answer at this time (1:0/0/0) What timing source are you using? Any other factors that may be affecting this? By: John Covert (jcovert) 2011-01-27 18:16:47.000-0600 Power PC Mac OS X 10.4.11 Have been running Asterisk on it since 0.9. I believe the current problem started when I moved from 1.6.1.6 to 1.6.2.6 last May. You may not need Mac OS to reproduce, but you might need the same timing module. If you look at other similar reports, you may see that most of them are from people who have no hardware timing. That was not a problem in earlier versions. By: Sean Bright (seanbright) 2011-01-27 19:16:21.000-0600 And you're using res_timing_dahdi or res_timing_pthread? ('module show like res_timing' from the CLI) By: John Covert (jcovert) 2011-01-27 22:00:42.000-0600 didn't I answer that in (0131146) or have I not been keeping up? where do I download dahdi-darwin? res_timing_pthread is my only choice, right? By: John Covert (jcovert) 2011-01-28 01:31:28.000-0600 To reproduce this problem, I'm pretty sure that you're going to have to get the machine really busy. I am convinced that in the changes from 1.6.1.6 to 1.6.2.6 a code change was introduced which created an n-squared (or n-factorial or worse) inefficiency bug. I have two different systems which are identical except for processor speed. I have been running my production PBX on the slower, older machine. The faster one is used for other work, and for pre-testing new releases of asterisk before they are deployed into production. I have been reporting this problem from the production machine. It has some 30 sip peers and 5 or six iax peers. The problem happens ALL THE TIME on the slower production machine. On the faster test machine, simply doing the originate command is not sufficient to cause the visible problem (though IAX audio is very choppy and pretty unintelligible). Consider the following CPU usage when the production asterisk is just running "idle" -- doing nothing but processing registrations, qualifies, ping/pongs, and other keepalives on sip and iax: 29189 asterisk 5.2% 12:18.40 36 721 1085 38.6M 25.0M 46.4M 200M Now, watch what happens when I start the test using the originate command: 29189 asterisk 103.9% 13:15.61 >> 824 1291 40.8M+ 25.0M 48.6M+ 224M+ Once stopped it drops back down: 29189 asterisk 5.6% 14:17.36 >> 821 1285 41.0M 25.0M 48.8M 224M A similar thing happens on the faster machine, but it has enough headroom that there are no messages unless some additional load (e.g. top sorted by %usage). Yet it is still choppy. By: Sean Bright (seanbright) 2011-01-28 06:21:23.000-0600 Great. I'll use res_timing_pthread in my tests here. Thanks. By: John Covert (jcovert) 2011-01-29 08:42:48.000-0600 seanbright - you might look to see if any of the uploads I've put in 18511 help with your investigation. By: John Covert (jcovert) 2011-02-06 08:32:06.000-0600 seanbright -- here is more data for you. I just decided to try backing out the code change right around this error message in channel.c which was introduced somewhere between 1.6.1.6 and 1.6.2.6. That's when the problem became noticeable to me an many others. While it doesn't completely eliminate the error messages (which I didn't really expect it to), it does make IAX audio usable again. Without backing out the change, calls on my inbound IAX trunk at 206-203-6610 were basically unintelligible, and with it, things work again. I don't think this patch is the right solution, but it basically demonstrates that some of the work done here, and the queue handling in general was/is simply so inefficient that it is nearly unusable. I'm seeing the "Exceptionally long queue" messages on the local channel on one of my clients 2.5 GHz machines whenever some other process puts some load on the machine. I've uploaded backout-channel.c.patch for informational purposes. /john By: Alec Davis (alecdavis) 2011-02-06 17:07:40.000-0600 Picking up on the unintelligable speech; The symptom was unintelligable speech in one direction, other direction was fine. Last week we had a similar unintelligable speech experience after upgrading a debian box from 1.6.1 to 1.8.2 with no DAHDI hardware, in asterisk.conf internal_timing=yes was required. The other box was already at 1.8.2 with internal_timing=yes and has DAHDI hardware. By: John Covert (jcovert) 2011-02-06 18:24:28.000-0600 Hah. Definitely don't want to try internal_timing=yes on Power PC / Mac OS X. Wham. [Feb 6 19:21:43] WARNING[2473]: app_dial.c:1328 wait_for_answer: Unable to write frame [Feb 6 19:21:43] WARNING[2473]: app_dial.c:1328 wait_for_answer: Unable to write frame [Feb 6 19:21:43] WARNING[2473]: app_dial.c:1328 wait_for_answer: Unable to write frame [Feb 6 19:21:43] WARNING[2473]: app_dial.c:1328 wait_for_answer: Unable to write frame [Feb 6 19:21:43] WARNING[2473]: app_dial.c:1328 wait_for_answer: Unable to write frame etc. By: John Covert (jcovert) 2011-02-16 18:57:26.000-0600 1.8.3-rc2: Originating station is ulaw. Transcoding seems to make the problem worse. Can you try to reproduce this on an older, slow machine? Or with another process using up most of the CPU on a faster machine? No Digium hardware installed for timing. -- Executing [8344@dialstation:2] Dial("SIP/x21-00000003", "IAX2/pbx.digium.com/s,120") in new stack -- Called pbx.digium.com/s -- Call accepted by 216.207.245.8 (format gsm) -- Format for call is gsm -- IAX2/216.207.245.8:4569-6503 answered SIP/x21-00000003 [Feb 16 17:49:34] WARNING[16181]: channel.c:1434 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/216.207.245.8:4569-6503 [Feb 16 17:49:34] WARNING[16181]: channel.c:1434 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/216.207.245.8:4569-6503 [Feb 16 17:49:34] WARNING[16181]: channel.c:1434 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/216.207.245.8:4569-6503 [Feb 16 17:49:34] WARNING[16181]: channel.c:1434 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/216.207.245.8:4569-6503 [Feb 16 17:49:34] WARNING[16181]: channel.c:1434 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/216.207.245.8:4569-6503 [Feb 16 17:49:34] WARNING[16181]: channel.c:1434 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/216.207.245.8:4569-6503 By: John Covert (jcovert) 2011-02-20 23:50:07.000-0600 I'm now on 1.8.3-rc3. Was still having trouble with IAX. Did this: ; Establishes the number of iax helper threads to handle I/O. ; iaxthreadcount = 10 iaxthreadcount = 2 ; jrc iaxmaxthreadcount = 2 ; jrc ; Establishes the number of extra dynamic threads that may be spawned to handle I/O ; iaxmaxthreadcount = 100 This seems to improve things, though audio is still sometimes quite choppy. Don't have a lot of experience with this yet; just did it a few minutes ago, but the originate sip/x28 application dial iax2/iax.covert.org/ringnoanswer test, which used to instantly produce the long queues, no longer does so. This continues to validate my belief that something very inefficient is going on somewhere. Queue handling; thread handling; both? **** Update: I am on 1.8.3.2 now and have had to set these two threadcount params to 1. I have also tried the ast_indicate removal patch suggested in issue ASTERISK-16711 but I still get the long queues if I go to the default threadcounts. By: Sean Bright (seanbright) 2012-02-17 15:19:02.922-0600 I just committed a timing related fix to the IAX2 channel driver that affects the timing in which trunked IAX2 packets are sent. It will be in 1.8.11 whenever that is released (it's commit [r355746|http://svnview.digium.com/svn/asterisk?view=revision&revision=355746] in the 1.8 branch - here's a [direct link|http://svnview.digium.com/svn/asterisk/branches/1.8/channels/chan_iax2.c?view=patch&r1=355746&r2=355745&pathrev=355746] to the unified diff). I know that it has been almost a year since your last comments on the matter so I assume you have migrated away from IAX2. If not, give that commit a shot and let us know if it improves anything for you. *Edit:* This would have affected all versions of Asterisk starting with 1.6.1. By: Matt Jordan (mjordan) 2013-02-24 18:23:04.527-0600 Can anyone confirm if this is still a problem with {{chan_iax2}} after 1.8.11? By: Matt Jordan (mjordan) 2015-03-14 17:41:32.909-0500 Per the Asterisk versions page [1], the maintenance (bug fix) support for the Asterisk branch you are using has ended. For continued maintenance support please move to a supported branch of Asterisk. After testing with a supported branch, if you find this problem has not been resolved, please open a new issue against the latest version of that Asterisk branch. Thanks! [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions | ||