[Home]

Summary:ASTERISK-17772: mutex 'current_dest_chan' freed more times than we've locked! on bridge() from dialplan
Reporter:Jacco van Tuijl (jacco)Labels:
Date Opened:2011-04-29 09:00:34Date Closed:2011-07-21 12:01:02
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/General
Versions:1.8.4 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) backtrace.txt
( 1) bridge_exex.patch
( 2) gdb.txt
( 3) valgrind.txt
Description:Sometime when bridging I get this error:
[Apr 29 15:36:00] ERROR[5486]: lock.c:407 __ast_pthread_mutex_unlock: features.c line 5872 (bridge_exec): mutex 'current_dest_chan' freed more times than we've locked!
[Apr 29 15:36:00] ERROR[5486]: lock.c:438 __ast_pthread_mutex_unlock: features.c line 5872 (bridge_exec): Error releasing mutex: Operation not permitted

normaly bridging goes okay or it tells me the channel does not exist

****** STEPS TO REPRODUCE ******

I've made this stupid dialplan that will reproduce it:
[debug]
exten = _X.,1,answer
exten = _X.,n,macro(DoBridging,${CHANNEL})
exten = _X.,n(waiting),wait(15)
exten = _X.,n,goto(waiting)

[macro-DoBridging]
exten = s,1,Set(DB(temp/bridgechannel)=${ARG1})
exten = s,n,Originate(local/100@DoBridging,exten,dummy,100)

[DoBridging]
exten = 100,1,answer()
exten = 100,n,Bridge(${DB(temp/bridgechannel)})

[dummy]
exten = _X.,1,answer()
exten = _X.,n,set(TIMEOUT(absolute)=0)
exten = _X.,n,wait(1000000)
exten = _X.,n,hangup()
Comments:By: Jacco van Tuijl (jacco) 2011-04-29 09:07:13

use this dialplan to reproduce:
[debug]
exten = _X.,1,answer
exten = _X.,n,macro(DoBridging,${CHANNEL})
exten = _X.,n(waiting),wait(15)
exten = _X.,n,goto(waiting)

[macro-DoBridging]
exten = s,1,Set(DB(temp/bridgechannel)=${ARG1})
exten = s,n,Originate(local/100@DoBridging,exten,dummy,100)

[DoBridging]
exten = 100,1,answer()
exten = 100,n,Bridge(${DB(temp/bridgechannel)})

[dummy]
exten = _X.,1,answer()
exten = _X.,n,set(TIMEOUT(absolute)=0)
exten = _X.,n,wait(1000000)
exten = _X.,n,hangup()
By: Jacco van Tuijl (jacco) 2011-05-02 05:28:17

more debug info from the last time the error accured; this time resulting into a crash with coredump:
[May  2 12:18:06] ERROR[25725]: lock.c:407 __ast_pthread_mutex_unlock: features.c line 5872 (bridge_exec): mutex 'current_dest_chan' freed more times than we've locked!
[May  2 12:18:06] ERROR[25725]: lock.c:438 __ast_pthread_mutex_unlock: features.c line 5872 (bridge_exec): Error releasing mutex: Operation not permitted
[May  2 12:18:06] ERROR[25728]: lock.c:396 __ast_pthread_mutex_unlock: features.c line 5872 (bridge_exec): attempted unlock mutex 'current_dest_chan' without owning it!
[May  2 12:18:06] ERROR[25728]: lock.c:398 __ast_pthread_mutex_unlock: features.c line 5226 (do_bridge_masquerade): 'current_dest_chan' was locked here.
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk(ast_bt_get_addresses+0x19) [0x8120d11]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk(__ast_pthread_mutex_lock+0xb5) [0x811a417]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk(__ao2_lock+0x4a) [0x8087b64]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk [0x80fdfed]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk [0x8100cc7]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk(pbx_exec+0x1ea) [0x8138a2d]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/lib/asterisk/modules/app_exec.so [0xb685d0f3]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk(pbx_exec+0x1ea) [0x8138a2d]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk [0x8141b07]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk(ast_spawn_extension+0x53) [0x81434fd]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk [0x8143ea2]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk [0x8145935]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /usr/sbin/asterisk [0x819717d]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /lib/i686/cmov/libpthread.so.0 [0xb72ab4c0]
[May  2 12:18:06] ERROR[25728]: /usr/src/asterisk-1.8.4-rc3/include/asterisk/lock.h:302 __dump_backtrace: /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb74db84e]
[May  2 12:18:06] ERROR[25728]: lock.c:438 __ast_pthread_mutex_unlock: features.c line 5872 (bridge_exec): Error releasing mutex: Operation not permitted
By: Jacco van Tuijl (jacco) 2011-05-02 05:36:36

added backtrace files
By: Jacco van Tuijl (jacco) 2011-05-03 04:02:53

added valgrind.txt
By: Jacco van Tuijl (jacco) 2011-05-10 02:51:30

this line is features.c is generating the error:
ast_channel_unlock(current_dest_chan);

if I add this line above it:
ast_channel_lock(current_dest_chan);

the error nolonger shows
By: Jacco van Tuijl (jacco) 2011-07-05 06:41:10.360-0500

here is some logging that shows more details on this bug : http://pastebin.com/HU1rKrBJ
this log is generated by asterisk 1.8.4.2

By: Gregory Hinton Nietsky (irroot) 2011-07-05 06:44:59.866-0500

Patch based on IRC chat with Jacc0
By: Gregory Hinton Nietsky (irroot) 2011-07-05 06:53:48.959-0500

seems bridge_exec is expecting ast_channel_get_by_name_prefix to return a locked channel this is not so it returns channel with ref count inc we must not unlock but deref it based on similar usage.
By: David Vossel (dvossel) 2011-07-20 16:33:33.888-0500

The channel is not locked when returned by ast_channel_get_by_name().  I'm not sure why we unlock the channel, it is likely at one point the channel was locked, then the code locking the channel was removed without removing the unlock.

It appears that the current_dest_chan has it's refcount properly decremented later on in the function.  The right solution is probably just to remove that ast_channel_unlock call. It does nothing.
By: Richard Mudgett (rmudgett) 2011-07-21 12:00:33.492-0500

Committed to -r329146 trunk

Merged revisions 329145 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/10

................
 r329145 | rmudgett | 2011-07-21 11:52:17 -0500 (Thu, 21 Jul 2011) | 16 lines

 Merged revisions 329144 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.8

 ........
   r329144 | rmudgett | 2011-07-21 11:46:21 -0500 (Thu, 21 Jul 2011) | 9 lines

   Dialplan bridge() app mutex 'current_dest_chan' freed more times than we've locked!

   This appears to be a leftover from when ast_channel was converted to ao2
   objects.

   Simply removed the extraneous unlock.

   (closes issue ASTERISK-17772)
 ........
................