Summary:ASTERISK-06820: MixMonitor() causes Asterisk to deadlock under good call volume
Reporter:Edward Eastman (whisk)Labels:
Date Opened:2006-04-20 17:43:53Date Closed:2006-12-05 09:01:47.000-0600
Versions:Frequency of
Environment:Attachments:( 0) asterisk_bt.txt
( 1) asterisk_bt_full_-_post_patch.txt
( 2) asterisk_bt_full_-_post_patch_2.txt
( 3) asterisk_bt_full_-_post_patch_3.txt
( 4) asterisk_problem_extensions_excerpt.txt
Description:We have a couple asterisk box acting as sip gateways/call recorders (using mixmonitor) for a call centre seeing c. 4000 calls/day. After a while I see an 'Avoided initial deadlock' message every time I do 'show channels' even once the server has no calls on it (and there is one channel shown even with 0 calls).  Once asterisk gets into this state only a restart will fix it.  Sometimes it seems happy like that for some time, others it crashes.

We're seeing the warnings on show channels within 15-30 mins after a restart if there's 30+channels in use, but the crash is much more variable - probably once every 1-2 days on average.

I haven't been able to reproduce this if i take out the mixmonitor recording although I haven't tested it like this for too long.

I've attached a 'thread apply all bt' from an affected asterisk together with relevant portions of extensions.conf
Comments:By: Edward Eastman (whisk) 2006-04-20 17:49:50

Oh, few more details - the servers are accepting sip calls from another asterisk server, recording them to local hdds and passing them on to a tdm switch/acd system over pri.

I've also noticed this problem with earlier 1.2s and trunk from a couple of weeks ago (haven't tried latest trunk)

By: Tilghman Lesher (tilghman) 2006-04-20 18:23:03

Do all of the channels connect and bridge, or do any of them get hung up before bridging?

By: Edward Eastman (whisk) 2006-04-20 18:42:09

Yes I'm pretty sure they're all bridging

By: Tilghman Lesher (tilghman) 2006-04-20 18:46:40

Please test this patch to see if it makes a difference.

By: Edward Eastman (whisk) 2006-04-21 16:15:12

Thanks for you help with this - I've tried the patch on one of our servers today, with mainly good results - we didn't have any crashes, and we didn't have any lost calls, but the warning still comes up, although I think it took longer to show than normal. Here it is btw:

CLI> show channels
Channel              Location             State   Application(Data)
0 active channels
10 active calls
Apr 21 21:58:17 WARNING[16609]: channel.c:787 channel_find_locked: Avoided initial deadlock for '0xb5b1c270', 10 retries!

It was a fairly busy day today, and I'd have expected some problems (crashes/lost calls) based on past form, but it seemed better.  I'm pretty sure (although I wouldn't swear) that the show channels prior to this patch only showed 1 active call rather than 10.

I've just done a thread apply all bt on the running asterisk and this time there are only 29 threads - i've attached it although i'm not sure how helpful it will be as it's from a normal asterisk make (no valgrind etc). I'll try and get a non-optimized one as well.

By: Tilghman Lesher (tilghman) 2006-04-21 17:00:30

Actually 29 threads sounds about right, considering how many monitor threads we have in various modules.  I wouldn't worry about the warning message.  It happens, even on perfectly functioning systems (it's a side effect of having devicestate).

By: Edward Eastman (whisk) 2006-04-22 17:40:06

This's been running today, and the problem hasn't reoccurred since a restart last night.  Todays traffic has been much less (generally around 15 concurrent calls rather than 40-50) but I'm pretty sure that before this patch it would've reoccurred.  I did do a test last night and ran a load of calls through and it did reoccur - there's a bt attached (post patch 2) which does show a large number of threads again - so I think while the patch has improved matters it hasn't completely fixed it?

By: Edward Eastman (whisk) 2006-04-24 16:51:18

Been running it for another day (c. 2600 calls), and again the warning took much longer to show up than before the patch, but it still did appear - I'll attach another bt.

By: Edward Eastman (whisk) 2006-04-26 16:07:15

I'm afraid I think this definately hasn't fixed the problem - we had a higher call volume and had a couple of full deadlocks (couldn't receive any incoming calls) - these seem to occur when the box is high on cpu. I did get a bt but typically my pc crashed before I saved it :/

Any other ideas?

By: Serge Vecher (serge-v) 2006-05-03 09:58:00

Whisk: there was a fix committed to 1.2 yesterday that may impact this issue. Can you please download the latest 1.2 branch (1.2.8 which will contain it, has not been released yet). Thanks.

By: Edward Eastman (whisk) 2006-05-03 11:02:26

OK - I'll test later on today - should I test this without Corydon's additional patch or with?

By: Serge Vecher (serge-v) 2006-05-03 11:17:33

first without, if the problem is still there, then with the patch.

By: Edward Eastman (whisk) 2006-05-05 17:14:21

I've been using 1.2 branch for the last few days and the problem still persists.  It looks like Corydon's patch is already in there.

By: BJ Weschke (bweschke) 2006-05-05 17:33:57

Whisk: current 1.2 branch does not yet contain Corydon's patch. Pls apply the patch and try and see if you're having the problem.

By: Edward Eastman (whisk) 2006-05-06 04:19:23

Are you sure about that? I've just done a fresh "svn co http://svn.digium.com/svn/asterisk/branches/1.2 asterisk" and then tried the patch:

# patch -p0 < /root/patch.mixmonitor
patching file channel.c
Reversed (or previously applied) patch detected!  Assume -R? [n] n
Apply anyway? [n] n
Skipping patch.
2 out of 2 hunks ignored -- saving rejects to file channel.c.rej

When I look at channel.c it looks very much like it's been applied already.

By: BJ Weschke (bweschke) 2006-05-06 08:32:00

Whisk: not sure why you're having a problem with patch but Corydon76's patch is definitely not in the current 1.2 branch. I will try and take a look later today if you're still having problem integrating the code.

By: Tilghman Lesher (tilghman) 2006-05-06 09:04:49

You may need to 'svn update'.  The patch was in the tree briefly for half an hour two weeks ago.

By: Edward Eastman (whisk) 2006-05-06 16:38:41

Sorry, /me hits self with the stupid stick (I was applying a completely wrong patch)

I'll apply Corydon's patch to latest 1.2 and see if that improves matters.

By: Vahram Igityan (vx) 2006-05-07 15:41:53

I am running Asterisk,  using only chan_h323 + agi script for managing passed traffic.

Every day I am getting mentioned warning while doing show channels, but calls are passing ok, but I cannot stop asterisk asterisk -rx 'stop now' from the cli any more, only kill is helping.
Hope it will help.

By: BJ Weschke (bweschke) 2006-05-09 19:33:10

I've got a /trunk system now exhibiting the same behavior. I'm trying to see what it takes to reproduce as this is a fairly high volume system and I've got the bottle held out to try and catch the bolt of lightning. :-/

By: Serge Vecher (serge-v) 2006-05-10 14:18:11

vx: do you also use mixmonitor like whisk? If not, your issue maybe different.

if mixmonitor is used, please try Corydon76's patch posted earlier 20060420__bug7004.diff.txt


By: Edward Eastman (whisk) 2006-05-10 14:22:38

I've been running the latest 1.2 branch for the last few days - and doesn't seem to make any difference - again it seems a little better with corydon's patch, but still the same problems surface - in summary the latest changes to 1.2 branch seem to have made no difference to the problem.

By: Vahram Igityan (vx) 2006-05-10 14:50:09

vechers: no, I am not using spy monitor.
I guess the source of problems is not a monitor, imho it is global deadlock caused by chan_h323 problem.
I will install last trunk and check with new patches (there are a  lot of changes for chan_h323), if the problem with nonstopable asterisk and deadlock message appears I will create a separate issue with backtraces.
Thank You.

By: Serge Vecher (serge-v) 2006-05-22 13:28:31

vx: I believe that your problem is not related to this (7004) bug, but to 5982. Please post your findings in that bug report. Thank you.

By: davet (davet) 2006-05-24 04:07:24

I have seen exactly the same problem and spent some time checking the configuration files and reloading zaptel drivers and constant restarts (had to "kill -9" since "stop now" didn't work) before taking a step back and looking for a simpler explanation.

The symptoms were exactly as you describe. "show channels" doesn't return useful channel information except errors like:
May 22 21:18:33 WARNING[29559]: channel.c:787 channel_find_locked: Avoided deadlock for '0x82a00c8', 10 retries!

I eventually traced it to a full /var partition.

I am running MySQL with its tables in /var/lib/mysql and CDRs were being written to /var/log/asterisk. I don't know whether the MySQL module was causing this blocking or the generic CDR CSV code but clearing space on /var and a restart fixed it.

Where are you writing your temporary -in and -out mix files to? Is this an explanation for you?

By: Serge Vecher (serge-v) 2006-05-26 12:34:29

whisk: please checkout the latest 1.2 branch code (>rev. 30546). A fix was just committed that should resolve the locking issues in app_queue. Please report and test back -- thank you!

By: Edward Eastman (whisk) 2006-05-26 16:37:09

We aren't using app_queue I'm afraid - just straight pushing of calls from SIP out to PRI with mixmonitor (extensions excerpt is in the attached files).  

Just to recap this problem is definately linked to mixmonitor - if I remove mixmonitor it goes away - and while Corydon's broadcast patch does seem to help, it doesn't resolve the issue.

By: BJ Weschke (bweschke) 2006-05-31 05:56:49

Whisk: Going back in your logs right around when this happens, do you see messages to the extent of "Dropping voice frame because we're still dialing" on a zap channel that has the lock?

By: Serge Vecher (serge-v) 2006-06-08 15:39:16

whisk: could you please try to see if that makes a difference? There is a major security update incorporated into it, so you should upgrade regardless.


By: Edward Eastman (whisk) 2006-06-09 07:12:06

Bweschke: I can't see any messages like that in the logs - any special settings needed to see them?

Vechers - I'll give it a go and let you know.

By: Serge Vecher (serge-v) 2006-06-09 08:47:41

whisk: make sure your logger.conf has the following line:
  console => notice,warning,error,debug

Restart Asterisk and at CLI, type set debug 4, set verbose 4.

Then will log very detailed debugging information. Thanks.

By: Serge Vecher (serge-v) 2006-06-19 13:17:01

ok, so what happened here?

By: Edward Eastman (whisk) 2006-06-19 16:39:33

I haven't had a chance to install until tonight - so i'll let you know how it goes  tomorrow.

By: Serge Vecher (serge-v) 2006-06-19 20:52:07

whisk: actually please update to the latest stable 1.2 revision. Joshnet/kpfleming have done some important code rewrites in r33725/r33842 for app_mixmonitor. These will be in 1.2.10 when that is released. Thanks.

By: Edward Eastman (whisk) 2006-06-20 17:01:14 was no different, but i'll try 1.2 branch latest and see what that does - should I try corydon's patch with this version as well?

By: Tilghman Lesher (tilghman) 2006-06-20 17:09:53

As that patch did not conclusively fix anything, I am removing it from this bug.  You should not apply it going forward.

By: Edward Eastman (whisk) 2006-06-20 17:41:30

Latest 1.2 branch crashes fairly firmly very quickly, i've had enough of tonight but i'll post a proper bug report tomorrow :)

By: Serge Vecher (serge-v) 2006-06-27 14:42:07

Actually: hold of on that patch until it is rewritten. In either case, please monitor 7230 as the solution there will probably impact your case also. Thanks

Whisk: could you please try the patch 2006-06-27-channel.c-M7230.patch in Bug ASTERISK-7043. There is a good chance that it will fix your problem also. Thanks.

By: Edward Eastman (whisk) 2006-07-24 04:42:39

OK - as suggested in bug 7230 I've commented out the ast_channel_spy_remove in stopmon - the reasoning being (as i understand it) that it's called from channel.c on channel hangup anyway, and this can cause a race/deadlock condition. Can anyone confirm that this is a safe/sensible thing to do? It's been running for a day so far without any problems, but that was with fairly low call volume so I'll report back in a day or so.

By: Matt Riddell (zx81) 2006-08-20 11:30:24

We're getting the same thing on SIP Calls to MaxTNT with a DS3.

The patch in 7230 doesn't help us.

The only thing that helps is removing MixMonitor.

By: Michael Toop (mmmmmtoop) 2006-09-01 04:17:34

Getting exactly the same symptoms by NOT using MixMonitor.  We stopped using MixMonitor when it caused a complete deadlock and eventual crash.  Now it looks 'partial' with Monitor, Asterisk continues running but the 'show channels' command displays:  Avoided deadlock and only shows a few channels.

By: Serge Vecher (serge-v) 2006-09-01 09:25:34

ok, we need to know if this is observed on 1.2.11 or trunk or what?

By: Serge Vecher (serge-v) 2006-09-05 15:25:21

actually, make that revision 42054 (or higher) of 1.2 branch.

By: Michael Toop (mmmmmtoop) 2006-09-06 15:28:00

Sorry...Observed on SVN-tag-1.2.11-r40846

By: Joshua C. Colp (jcolp) 2006-09-06 15:31:19

That is a check out of 1.2.11 which DOES NOT have my latest fixes in it, you need to check out the 1.2 branch from SVN to get them.

By: Joshua C. Colp (jcolp) 2006-09-06 15:32:08

Misread your statement as it was in reply to serge - so please check out the 1.2 branch to get my fixes.

By: Joshua C. Colp (jcolp) 2006-09-18 10:23:49

No responses people, but that's okay. If an issue still exists please reopen this bug. (Yes I know I have just copy/pasted this)

By: Jared Smith (jsmith) 2006-12-05 09:01:47.000-0600

This problem may be related ot 8376, according to a note in bug 8376.