Bug #17783
Updated by nobu (Nobuyoshi Nakada) about 3 years ago
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' ```