Attempt to unlock a mutex which is not locked (ThreadError)

[valerii.hiora@…]

$ DYLD_LIBRARY_PATH=. ./macruby -e "require 'net/imap'; imap = Net::IMAP.new('imap.gmail.com', 993, true); imap.login('somebody','somepassword')"

core:in `unlock': Attempt to unlock a mutex which is not locked (ThreadError)

from monitor.rb:178:in `mon_exit'
from monitor.rb:192:in `synchronize'
from core:in `send_command:'
from core:in `login:'
from -e:in `<main>'

Inspecting imap object from irb and macirb shows that latter has a mutex and seems it causes problem

[valerii.hiora@…]

Forgot to mention - rev. 3225

[lsansonetti@…]

Still reproduces the bug on trunk. Screening for 1.0.

[jhemmelg@…]

I think I have a possible reduction for this problem. I was prototyping some thread code for work and tried it out on macruby version 0.8. It acts like a race condition. Mostly it manifests with the error about unlocking an unlocked mutex, but I have had it end up with the mutex locked and the threads blocked. Here is a sample of running the script:

$ macruby testThreadComm.rb 
0
^C
$ macruby testThreadComm.rb 
0
1251879
2504224
3709045
5051891
6291455
7625310
8934016
$ macruby testThreadComm.rb 
0
1315628
2659968
3938967
testThreadComm.rb:62:in `<main>': Attempt to unlock a mutex which is not locked (ThreadError)

The first time the program locked up and I had to kill it. I assume the mutex was locked, blocking progress on either thread. The second invocation is a clean run, and the third ends with the mutex being unlocked when it shouldn't be. Most of the time it completes without a problem.

[jhemmelg@…]

Two threads accessing a shared array with mutex protection

[lsansonetti@…]

Can't seem to reproduce this with master:

$ while [ 1 ]; do ./miniruby ~/Downloads/testThreadComm.rb; echo "success"; done
0
1688262
3351766
5159677
6707739
8514222
success
0
1628400
3246128
5025082
6485548
8201978
success
0
1493911
2982025
4382340
5925772
7175266
8740334
success
0
1631704
3286208
5036276
6494757
8242057
success
0
1572863
3145727
4845975
6291455
7963761
9713879
success
0
1600947
3170841
4972433
6364928
8142890
9920475
success
0
1573188
3178755
4901616
6297448
8064487
^C
$ 
$ 
$ 
$ 

[lsansonetti@…]

The reduction seems invalid, as I can still reproduce the problem when using net/imap:

$ DYLD_LIBRARY_PATH=. ./macruby -e "require 'net/imap'; imap = Net::IMAP.new('imap.gmail.com', 993, true); imap.login('somebody','somepassword')"
/Library/Frameworks/MacRuby.framework/Versions/0.11/usr/lib/ruby/1.9.2/monitor.rb:189:in `mon_exit': Attempt to unlock a mutex which is not locked (ThreadError)
	from /Library/Frameworks/MacRuby.framework/Versions/0.11/usr/lib/ruby/1.9.2/monitor.rb:203:in `synchronize'
	from -e:1:in `<main>'

[jhemmelg@…]

Replying to lsansonetti@…:

Can't seem to reproduce this with master:

It is still happening on my system. I get about 300,000 loops per second, so I get a lot more mutex lock/unlock cycles. Your machine is fast!

[jhemmelg@…]

I took a further look through the mutex code and found what I think is part of the problem. In the file thread.c, rb_mutex_unlock0(), line 1510:

	pthread_assert(pthread_mutex_unlock(&m->mutex));
	m->thread = NULL;

The assignment to m->thread is made after m->mutex is unlocked. This appears to create a race condition. I swapped these two lines and it made my test program work.

	m->thread = NULL;
	pthread_assert(pthread_mutex_unlock(&m->mutex));

With this change my test program no longer fails. However, the error from running the imap test has changed:

$ DYLD_LIBRARY_PATH=. ./macruby -e "require 'net/imap'; imap = Net::IMAP.new('imap.gmail.com', 993, true); imap.login('somebody','somepassword')"
/Library/Frameworks/MacRuby.framework/Versions/0.11/usr/lib/ruby/1.9.2/monitor.rb:189:in `mon_exit': Attempt to unlock a mutex which is locked by another thread (ThreadError)
	from /Library/Frameworks/MacRuby.framework/Versions/0.11/usr/lib/ruby/1.9.2/monitor.rb:203:in `synchronize'
	from -e:1:in `<main>'

I took a look at the code for MonitorMixin, which imap uses for the synchronize() call. It looks like the error I am getting is impossible, because the monitor code saves and checks the thread id outside of the mutex doing the same thing. The monitor code doesn't complain about the thread id's not matching but the mutex does. I will look into this further.

I can not be certain that there are no further race conditions in the mutex code. This is why this is not submitted as a patch.

I have a couple of questions about the mutex implementation. I was looking into the code for mutex in the 1.9.2-p136 release and it looks fairly different. In that code the thread variable is used as the ruby-level mutex variable, and the mutex is used only to protect access to it. Why are the implementations different and would it make sense to pull that implementation over? Alternatively, would an implementation of mutex using the high-performance semaphore from GCD be worth considering? Or would it be better to just review the existing code for race conditions and move on from there? I would be happy to work on this no matter the direction, but I don't want to waste time working on something that would not be acceptable to the team.

[watson1978@…]

I guess that your changing is correct. the following script did not work before applying your changing in my environment.

require 'thread'
m = Mutex.new
r = 0
max = 100
(1..max).map{
  Thread.new{
    i=0
    while i<max
      i+=1
      m.synchronize{
        r += 1
      }
    end
  }
}.each{|e|
  e.join
}

puts :finish

[watson1978@…]

This script would reproduce a issue.

require "monitor"

monitor = Monitor.new
cond = monitor.new_cond

a = "foo"
Thread.start do
  monitor.synchronize do
    a = "bar"
    cond.signal
  end
end

monitor.synchronize do
  p a
  cond.wait
  p a
end

$ ruby19 test_monitor.rb
"foo"
"bar"

$ macruby test_monitor.rb 
"foo"
"bar"
/Library/Frameworks/MacRuby.framework/Versions/0.11/usr/lib/ruby/1.9.2/monitor.rb:189:in `exit': Attempt to unlock a mutex which is not locked (ThreadError)
	from /Library/Frameworks/MacRuby.framework/Versions/0.11/usr/lib/ruby/1.9.2/monitor.rb:203:in `synchronize'
	from /Users/watson/tmp/test_monitor.rb:14:in `<main>'

[jhemmelg@…]

OK, I was looking further into this. It looks like the mutex is not re-locked when cond.wait returns in the main thread. The synchronize method then tries to unlock it and finds it already unlocked. The documentation for ConditionVariable::wait claims to re-lock the mutex on wakeup. I can't see where that is supposed to be happening. It may be some magic with the thread wakeup logic, but I can't see it in either the macruby code or the cruby 1.9.2 code. I'll try to keep digging but I wouldn't be disappointed if someone else figures it out first.

[jhemmelg@…]

Re-locking the mutex at the end of mutex_sleep() (in thread.c) seems to fix this problem completely. Pull request sent.

[watson1978@…]

Awesome! Thank you for your great works!

Fixed with  https://github.com/MacRuby/MacRuby/commit/a8e8922360d1e95c75483555eed570666ff95574