Bug #17783: Running sidekiq with ruby 3.0 (possible thread deadlock on resolv request_id allocation and free)

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: 3.0
• Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN

[junyulive (josh c)]

I have a simple sidekiq job running http request through net/http lib, many years (no issues with ruby 2.3-2.7.2), last week i upgraded to ruby 3.0, that simple job raise the following exception after running every 10+ hours, (restart sidekiq process will solve the problem), so I looked the error log, most of them are killed by the Timeout.timeout block when calling resolv.getaddress, raise the "execution expired" excepiton. dig in the thread deadlock may happened on resolv.rb:620, during the allocate_request_id. I have no experience on digging these thread issues, not sure what the root cause will be.

ruby/3.0.0/securerandom.rb:92:in `urandom'
ruby/3.0.0/securerandom.rb:92:in `gen_random_urandom'
ruby/3.0.0/securerandom.rb:71:in `bytes'
ruby/3.0.0/resolv.rb:606:in `random_number'
ruby/3.0.0/resolv.rb:606:in `random'
ruby/3.0.0/resolv.rb:625:in `block in allocate_request_id'
ruby/3.0.0/resolv.rb:622:in `synchronize'
ruby/3.0.0/resolv.rb:622:in `allocate_request_id'
ruby/3.0.0/resolv.rb:843:in `sender'
ruby/3.0.0/resolv.rb:527:in `block in fetch_resource'
ruby/3.0.0/resolv.rb:1125:in `block (3 levels) in resolv'
ruby/3.0.0/resolv.rb:1123:in `each'
ruby/3.0.0/resolv.rb:1123:in `block (2 levels) in resolv'
ruby/3.0.0/resolv.rb:1122:in `each'
ruby/3.0.0/resolv.rb:1122:in `block in resolv'
ruby/3.0.0/resolv.rb:1120:in `each'
ruby/3.0.0/resolv.rb:1120:in `resolv'
ruby/3.0.0/resolv.rb:521:in `fetch_resource'
ruby/3.0.0/resolv.rb:507:in `each_resource'
ruby/3.0.0/resolv.rb:402:in `each_address'
ruby/3.0.0/resolv.rb:116:in `block in each_address'
ruby/3.0.0/resolv.rb:115:in `each'
ruby/3.0.0/resolv.rb:115:in `each_address'
ruby/3.0.0/resolv.rb:93:in `getaddress'
ruby/3.0.0/resolv.rb:44:in `getaddress'
ruby/3.0.0/resolv-replace.rb:12:in `getaddress'
ruby/3.0.0/resolv-replace.rb:25:in `initialize'
ruby/3.0.0/net/http.rb:987:in `open'
ruby/3.0.0/net/http.rb:987:in `block in connect'
ruby/3.0.0/timeout.rb:107:in `timeout'
ruby/3.0.0/net/http.rb:985:in `connect'
ruby/3.0.0/net/http.rb:970:in `do_start'
ruby/3.0.0/net/http.rb:959:in `start'
ruby/3.0.0/net/http.rb:621:in `start'
# simple net/http request
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/execution.rb:48:in `block in perform_now'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
ruby/3.0.0/benchmark.rb:293:in `measure'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/activerecord-6.1.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:462:in `with_connection'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/i18n-1.8.10/lib/i18n.rb:314:in `with_locale'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/core_ext/time/zones.rb:66:in `use_zone'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/instrumentation.rb:21:in `block in instrument'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/notifications.rb:203:in `block in instrument'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/notifications.rb:203:in `instrument'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/instrumentation.rb:31:in `instrument'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/instrumentation.rb:14:in `block (2 levels) in <module:Instrumentation>'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/logging.rb:22:in `block in tag_logger'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/tagged_logging.rb:99:in `block in tagged'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/tagged_logging.rb:37:in `tagged'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/tagged_logging.rb:99:in `tagged'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/logging.rb:22:in `tag_logger'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/logging.rb:15:in `block (2 levels) in <module:Logging>'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:137:in `run_callbacks'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/execution.rb:47:in `perform_now'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/execution.rb:25:in `block in execute'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/railtie.rb:47:in `block (4 levels) in <class:Railtie>'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/execution_wrapper.rb:88:in `wrap'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/reloader.rb:72:in `block in wrap'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/execution_wrapper.rb:84:in `wrap'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/reloader.rb:71:in `wrap'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/railtie.rb:46:in `block (3 levels) in <class:Railtie>'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `instance_exec'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/callbacks.rb:137:in `run_callbacks'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/execution.rb:23:in `execute'
ruby/3.0.0/gems/activejob-6.1.3.1/lib/active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:196:in `execute_job'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:164:in `block (2 levels) in process'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/middleware/chain.rb:138:in `block in invoke'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/middleware/chain.rb:143:in `invoke'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:163:in `block in process'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/job_retry.rb:112:in `local'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/rails.rb:14:in `block in call'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/execution_wrapper.rb:88:in `wrap'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/reloader.rb:72:in `block in wrap'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/execution_wrapper.rb:88:in `wrap'
ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/reloader.rb:71:in `wrap'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/rails.rb:13:in `call'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:257:in `stats'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/job_logger.rb:13:in `call'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/job_retry.rb:79:in `global'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:124:in `block in dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/logger.rb:11:in `with'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/job_logger.rb:33:in `prepare'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:123:in `dispatch'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:162:in `process'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:78:in `process_one'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/processor.rb:68:in `run'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/util.rb:15:in `watchdog'
ruby/3.0.0/gems/sidekiq-6.2.0/lib/sidekiq/util.rb:24:in `block in safe_thread'

[xtkoba (Tee KOBAYASHI)]

This seems to be a duplicate of Bug #17781.

[jeremyevans0 (Jeremy Evans)]

• Is duplicate of Bug #17781: Resolv::DNS RequestID table allocations are never freed, causing DNS lookups to eventually hang added

[nobu (Nobuyoshi Nakada)]

• Description updated (diff)

[mame (Yusuke Endoh)]

• Status changed from Open to Closed

Fixed by 9edc162583a4f685332239f6249745ad9b518cbe.