Bug #16782: `lock': deadlock; recursive locking (ThreadError) in 2.7.1

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -
• Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN

[ioquatix (Samuel Williams)]

Using the latest async-http repo:

% bundle exec rspec spec/async/http/performance_spec.rb

Traceback (most recent call last):
	11: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/task.rb:258:in `block in make_fiber'
	10: from /home/samuel/.gem/ruby/2.7.1/gems/async-io-1.28.0/lib/async/io/socket.rb:73:in `block in accept'
	 9: from /home/samuel/.gem/ruby/2.7.1/gems/async-io-1.28.0/lib/async/io/server.rb:32:in `block in accept_each'
	 8: from /home/samuel/Documents/socketry/async-http/lib/async/http/server.rb:67:in `accept'
	 7: from /home/samuel/Documents/socketry/async-http/lib/async/http/protocol/http1/connection.rb:80:in `close'
	 6: from /home/samuel/.gem/ruby/2.7.1/gems/protocol-http1-0.12.0/lib/protocol/http1/connection.rb:135:in `close'
	 5: from /home/samuel/.gem/ruby/2.7.1/gems/async-io-1.28.0/lib/async/io/stream.rb:224:in `close'
	 4: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:164:in `close'
	 3: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `cancel_monitor'
	 2: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `close'
	 1: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `deregister'
/home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/wrapper.rb:215:in `lock': SIGTERM (SignalException)
	9: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/forked.rb:64:in `block in spawn'
	8: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork'
	7: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork'
	6: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/forked.rb:67:in `block (2 levels) in spawn'
	5: from /home/samuel/.gem/ruby/2.7.1/gems/async-container-0.14.1/lib/async/container/controller.rb:47:in `block in async'
	4: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:58:in `run'
	3: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:58:in `ensure in run'
	2: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:250:in `close'
	1: from /home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:250:in `close'
/home/samuel/.gem/ruby/2.7.1/gems/async-1.24.2/lib/async/reactor.rb:250:in `lock': deadlock; recursive locking (ThreadError)
    runs benchmark

Finished in 4.5 seconds (files took 0.2483 seconds to load)
2 examples, 0 failures

% ruby --version
ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]

About 1 in 10-100 runs will trigger this result. I also tried current head and could reproduce:

Running 2s test @ http://127.0.0.1:9294/
  8 threads and 8 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    10.35ms   14.03ms  46.73ms   78.86%
    Req/Sec     0.99k   454.60     2.30k    63.80%
  16122 requests in 2.10s, 787.51KB read
Requests/sec:   7675.89
Transfer/sec:    374.94KB
 4.66s    error: Async::Task [oid=0x1360] [pid=69337] [2020-04-13 15:40:21 +1200]
               |   ThreadError: deadlock; recursive locking
               |   → /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `lock'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `deregister'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `close'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:215 in `cancel_monitor'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:164 in `close'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:78 in `ensure in block (2 levels) in bind'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:78 in `block (2 levels) in bind'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/task.rb:258 in `block in make_fiber'
               |   Caused by Async::Stop: Async::Stop
               |   → /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/task.rb:66 in `yield'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:233 in `wait_for'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/wrapper.rb:124 in `wait_readable'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/generic.rb:220 in `async_send'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/socket.rb:62 in `accept'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/server.rb:36 in `accept_each'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:104 in `block in accept'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-io-1.28.0/lib/async/io/shared_endpoint.rb:76 in `block (2 levels) in bind'
               |     /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/task.rb:258 in `block in make_fiber'
Traceback (most recent call last):
	9: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:64:in `block in spawn'
	8: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork'
	7: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork'
	6: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:67:in `block (2 levels) in spawn'
	5: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/controller.rb:47:in `block in async'
	4: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:56:in `run'
	3: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:234:in `run'
	2: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:204:in `run_once'
	1: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:204:in `select'
/home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:204:in `lock': SIGTERM (SignalException)
	9: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:64:in `block in spawn'
	8: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork'
	7: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/group.rb:42:in `fork'
	6: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/forked.rb:67:in `block (2 levels) in spawn'
	5: from /home/samuel/.gem/ruby/2.8.0/gems/async-container-0.14.1/lib/async/container/controller.rb:47:in `block in async'
	4: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:58:in `run'
	3: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:58:in `ensure in run'
	2: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:250:in `close'
	1: from /home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:250:in `close'
/home/samuel/.gem/ruby/2.8.0/gems/async-1.24.2/lib/async/reactor.rb:250:in `lock': deadlock; recursive locking (ThreadError)
    runs benchmark

Finished in 4.56 seconds (files took 0.31919 seconds to load)
2 examples, 0 failures

It's relatively straight forward to reproduce.

[ioquatix (Samuel Williams)]

Total stab in the dark, but I wonder if it's because the signal handling is interrupting the same thread it's already on? Or something else weird?

[ko1 (Koichi Sasada)]

deadlock; recursive locking

seems not difficult error, the same thread tries to lock a mutex twice without unlocking.
can you check it?

[ioquatix (Samuel Williams)]

There is no locking on that line:

https://github.com/socketry/async/blob/v1.24.2/lib/async/wrapper.rb#L215

Maybe it happens somewhere inside CRuby or nio4r extension.

[ioquatix (Samuel Williams)]

• Status changed from Open to Closed

I have not seen this issue for a long time so it must be fixed.