So, I’ve definitely encountered this before, but not to this extent. On certain calls, something like this will happen:
[2021-01-30 09:47:33] WARNING[14164][C-00000004]: channel.c:1145 __ast_queue_frame: Exceptionally long queue length queuing to Local/monitor@carriercrosstalk-00000002;2
[2021-01-30 09:47:33] WARNING[14170][C-00000003]: channel.c:1145 __ast_queue_frame: Exceptionally long queue length queuing to Local/monitor@carriercrosstalk-00000002;1
In reality, these things appear HUNDREDS of times per second in the console and once this happens, it is a runaway train that cannot be stopped. channel request hangup all / core restart now, they all fail. CPU usage starts climbing, and eventually Asterisk or the server crashes and once Asterisk is restarted, all is well again. Based on this post, this seems to be indicative of a deadlock somewhere: Exceptionally long voice queue length queuing to Local
The above was all with Asterisk 13.38. I upgraded to Asterisk 18.2, and now the severity of the problem is lessened. Asterisk generally no longer crashes and only that call is hampered. However, I still get this:
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17947][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[Jan 30 18:25:05] -- Executing [talk@operator:58] GotoIf("Local/s@operatorcnet-0000002a;2", "0?nocando") in new stack
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[Jan 30 18:25:05] -- Executing [talk@operator:59] Set("Local/s@operatorcnet-0000002a;2", "j=1") in new stack
[Jan 30 18:25:05] -- Executing [talk@operator:60] Goto("Local/s@operatorcnet-0000002a;2", "o2") in new stack
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[Jan 30 18:25:05] -- Goto (operator,talk,15)
[Jan 30 18:25:05] -- Executing [talk@operator:15] Playback("Local/s@operatorcnet-0000002a;2", "custom/prompts/brianop/op/2_repeat/im-sorry-whats-the-number-again") in new stack
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[Jan 30 18:25:05] -- <Local/s@operatorcnet-0000002a;2> Playing 'custom/prompts/brianop/op/2_repeat/im-sorry-whats-the-number-again.ulaw' (language 'en')
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
[2021-01-30 18:25:05] WARNING[17952][C-00000022]: channel.c:1086 __ast_queue_frame: Exceptionally long queue length queuing to Local/s@operatorcnet-0000002a;2
So, it’s only maybe ~100 of these instead of 100s or 1000s of them every second. Much, much better. Also, the warnings are for a different dialplan context for some reason, even though I’m doing exactly the same thing to replicate, which is weird.
I wanted to see if there was a deadlock going on, because this still doesn’t seem right to me. I recompiled 18.2 with the following compiler options: DEBUG_THREADS , MALLOC_DEBUG , DONT_OPTIMIZE
and reinstalled.
I’ve been trying to replicate the issue, which replicates readily, and then trying to execute the following soon after I see all those queue warnings in the console:
/var/lib/asterisk/scripts/ast_coredumper --running --no- default -search
It dumps everything all right, but locks.txt is essentially empty, which makes it seem like there’s no deadlock.
Could there be some other issue going on, or is there a better way to try to figure out what the issue is here?