[ruby-core:100954] [Ruby master Bug#16782] `lock': deadlock; recursive locking (ThreadError) in 2.7.1

Issue #16782 has been updated by 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.

----------------------------------------
Bug #16782: `lock': deadlock; recursive locking (ThreadError) in 2.7.1
https://bugs.ruby-lang.org/issues/16782#change-88609

* Author: ioquatix (Samuel Williams)
* Status: Open
* Priority: Normal
* Assignee: ko1 (Koichi Sasada)
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
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.





-- 
https://bugs.ruby-lang.org/

Unsubscribe: <mailto:[e-mail]?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>