I have two clients running Asterisk 1.4.21.2 on Debian etch + Realtime.
The message: channel.c: Avoiding initial deadlock for channel keeps appearing.
Any ideas?! I’ve been debugging for the past three days and haven’t found anything yet.
What is going wrong?
I seem to recall that part of the bug reporting guidelines say never report a debug message as a bug, in itself.
My server just stop starting any new calls, doesn’t respond on CLI.
The only way I’ve found to get things working again is to reboot it.
I’ve collected gdb debug, but haven’t found anything that indicates a deadlock.
My full log has a lot of 4696587 [Dec 4 14:08:01] DEBUG[8460] channel.c: Avoiding deadlock for channel ‘0x8372348’
4697763 [Dec 4 14:08:06] DEBUG[3514] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
4697764 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697765 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697766 [Dec 4 14:08:06] DEBUG[8330] audiohook.c: Read factory 0xaf38dbc0 was pretty quick last time, waiting for them.
4697767 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697768 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697769 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697770 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697771 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697772 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697773 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697774 [Dec 4 14:08:06] DEBUG[8330] audiohook.c: Read factory 0xaf38dbc0 was pretty quick last time, waiting for them.
4697775 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697776 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697777 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697778 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697779 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697780 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697781 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697782 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697783 [Dec 4 14:08:06] DEBUG[8330] audiohook.c: Read factory 0xaf38dbc0 was pretty quick last time, waiting for them.
4697784 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697785 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697786 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697787 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697788 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697789 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697790 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697791 [Dec 4 14:08:06] DEBUG[8460] channel.c: Failure, could not lock ‘0x8372348’ after 199 retries!
4697792 [Dec 4 14:08:06] DEBUG[8330] audiohook.c: Read factory 0xaf38dbc0 was pretty quick last time, waiting for them.
4697793 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697794 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697795 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697796 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697797 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697798 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697799 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697800 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697801 [Dec 4 14:08:06] DEBUG[8330] audiohook.c: Read factory 0xaf38dbc0 was pretty quick last time, waiting for them.
4697802 [Dec 4 14:08:06] DEBUG[8460] channel.c: Avoiding deadlock for channel '0x8372348’
4697803 [Dec 4 14:08:06] DEBUG[3514] chan_sip.c: = No match Their Call ID: 100c6f18-3021fac-13c4-4937d750-3eb4eeb3-4937d750 Their Tag 100c2 b08-3021fac-13c4-4937d750-169f0933-4937d750 Our tag: as30dbd24f
4697804 [Dec 4 14:08:06] DEBUG[3514] chan_sip.c: = Found Their Call ID: 100c6f18-3021fac-13c4-4937d750-4b80237-4937d750 Their Tag 100c31a8- 3021fac-13c4-4937d750-2055e72c-4937d750 Our tag: as10b58a1d
And…there’s over 1000000 lines on my full log with:
5836389 [Dec 4 14:24:26] DEBUG[8330] audiohook.c: Failed to get 160 samples from write factory 0xaf38e5dc
5836390 [Dec 4 14:24:26] DEBUG[3462] channel.c: Dropping voice to exceptionally long queue on DGV/18
5836391 [Dec 4 14:24:26] DEBUG[8330] audiohook.c: Failed to get 160 samples from write factory 0xaf38e5dc
5836392 [Dec 4 14:24:26] DEBUG[3462] channel.c: Dropping voice to exceptionally long queue on DGV/18
5836393 [Dec 4 14:24:26] DEBUG[8330] audiohook.c: Failed to get 160 samples from write factory 0xaf38e5dc
5836394 [Dec 4 14:24:26] DEBUG[3462] channel.c: Dropping voice to exceptionally long queue on DGV/18
5836395 [Dec 4 14:24:26] DEBUG[8330] audiohook.c: Failed to get 160 samples from write factory 0xaf38e5dc
5836396 [Dec 4 14:24:26] DEBUG[3462] channel.c: Dropping voice to exceptionally long queue on DGV/18
5836397 [Dec 4 14:24:26] DEBUG[8330] audiohook.c: Failed to get 160 samples from write factory 0xaf38e5dc
5836398 [Dec 4 14:24:26] DEBUG[3462] channel.c: Dropping voice to exceptionally long queue on DGV/18
…
so, I restarted my server.
You won’t see a deadlock because the code gives up the resource and tries again later, if it is not immediately available, giving up completely, eventually.
Your question should be why is the resource locked so much of the time. I would suspect you are doing some sort of polling operation on it at a very high rate.)
However, if the CLI is completely frozen, rather than just very slow, you probably do have a deadlock somewhere.
If you haven’t already done so, you should create a NOOPTIMIZE build and also consider setting the other deadlock debugging options mentioned in the bug reporting guidelines.
I believe, that even when the CLI is locked up, it is often possible to start a new CLI instance and run the deadlock debugging tools.
Also, with gdb, look for threads that are waiting, then find the lock structure and find out which thread owns the lock.
The important point is that the Avoiding deadlock message is not a problem in itself, the problem is that you are getting them in large numbers and it is escalating to completely ignoring the resource, but even that wouldn’t explain a frozen CLI.
Thanks for your help. I’ll reinstall Asterisk first and debug it.
All the best.
Hi
This bug is similar bugs.digium.com/view.php?id=13116
also what are you doing when this happens ?
Ian
Last friday I reinstalled Asterisk, and it’s been working just fine since then.
I’ll get back here with my debugging infos.
Thanks.