Project

General

Profile

Bug #16782

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

Added by ioquatix (Samuel Williams) 8 months ago. Updated 5 days ago.

Status:
Open
Priority:
Normal
Target version:
-
[ruby-core:97864]

Description

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.

Updated by ioquatix (Samuel Williams) 8 months ago

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?

Updated by ko1 (Koichi Sasada) 7 months ago

deadlock; recursive locking

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

Updated by ioquatix (Samuel Williams) 5 days ago

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.

Also available in: Atom PDF