Undefined Method active_connection? for nil:NilClass

[jonathansimmons]

We made an update to Sidekiq yesterday, and connection_pool was updated simultaneously from 2.3.0 to 2.4.0. Since then, my rails app is locking up, requiring me to use Apple's activity monitor to stop the ruby process.

Whenever I attempt to send an email with my local database, I get the following errors:

Read error: #<NoMethodError: undefined method `[]' for nil:NilClass>
/Users/userfolder/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activerecord-7.0.4.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `active_connection?'

Is there something we need to change?

[mperham]

Can you include the full backtrace?

[jonathansimmons]

Dang, I had to restart my computer to get this functional again. I'm away from it now, but I'll get something added here as soon as I can get back to that branch.

[tisba]

We've seen the same issue in production and have rolled back to 2.3.0. Looks like we were also hit by https://github.com/drbrain/net-http-persistent/pull/144, maybe that's related, I'm not sure.

Some context: We do fork in a Sidekiq job (I know, I know it's not ideal, but it's working for years). This backtrace seems to be sidekiq internal though.

I have to look into creating a case to reproduce, unless @mperham already has an idea what is going on :)

Mar 29 10:24:48 host.example.com sidekiq[3875249]: 2023-03-29T08:24:48.621Z pid=3875249 tid=27cun WARN: NoMethodError: undefined method `[]' for nil:NilClass
Mar 29 10:24:48 host.example.com sidekiq[3875249]: 2023-03-29T08:24:48.621Z pid=3875249 tid=27cun WARN: /app/shared/bundle/ruby/3.2.0/gems/activerecord-7.0.4.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `active_connection?'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activerecord-7.0.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:42:in `disable_query_cache!'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activerecord-7.0.4.3/lib/active_record/query_cache.rb:43:in `block in complete'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activerecord-7.0.4.3/lib/active_record/query_cache.rb:43:in `each'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activerecord-7.0.4.3/lib/active_record/query_cache.rb:43:in `complete'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:37:in `before'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:423:in `block in make_lambda'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:199:in `block (2 levels) in halting'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:687:in `block (2 levels) in default_terminator'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:686:in `catch'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:686:in `block in default_terminator'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:200:in `block in halting'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:595:in `block in invoke_before'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:595:in `each'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:595:in `invoke_before'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:106:in `run_callbacks'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:143:in `complete'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:137:in `complete!'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:97:in `ensure in wrap'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:97:in `wrap'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/reloader.rb:71:in `wrap'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/rails.rb:15:in `call'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:135:in `block (4 levels) in dispatch'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:270:in `stats'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:130:in `block (3 levels) in dispatch'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/job_logger.rb:13:in `call'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:129:in `block (2 levels) in dispatch'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/job_retry.rb:80:in `global'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:128:in `block in dispatch'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/job_logger.rb:39:in `prepare'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:127:in `dispatch'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:175:in `process'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:82:in `process_one'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/processor.rb:72:in `run'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/component.rb:10:in `watchdog'
Mar 29 10:24:48 host.example.com sidekiq[3875249]: /app/shared/bundle/ruby/3.2.0/gems/sidekiq-7.0.7/lib/sidekiq/component.rb:19:in `block in safe_thread'

[mperham]

Cc @casperisfine, likely the same issue as n-h-p.

[tisba]

Cc @casperisfine, likely the same issue as n-h-p.

Just to avoid misunderstandings: Note that in the backtrace I pasted, n-h-p is not involved. We had two different issues/backtraces in prod.

[casperisfine]

This backtrace makes very little sense to me because ActiveRecord's ConnectionPool doesn't share any code with the connection_pool gem.

@tisba are you sure it's the only thing you updated? Not saying there is no bug, but I don't see how this gem would have introduced it.

[casperisfine]

Some context: We do fork in a Sidekiq job (I know, I know it's not ideal, but it's working for years). This backtrace seems to be sidekiq internal though.

Ok, I see what is happening to you, but it's not related to this gem. fork is indeed not expected from inside a block that enabled query cache. I'll fix it in Rails.

[casperisfine]

https://github.com/rails/rails/pull/47807

[mscrivo]

@casperisfine I think this might be affecting more than just rails ... we don't use rails and our tests started failing with the 2.4.0 upgrade. I have the following test:

      class SequelRobustMigrationsEnabledTest < Affinity::Test::Base
        describe 'Robust migrations are enabled' do
          it 'should have the safe migration wrapper method loaded in migrate script' do
            # We do this is a forked process because otherwise migrate.rb will be loaded
            # for other tests and cause them to fail, because DB.run will be overridden with
            # our robust migration wrapper.
            pid =
              fork do
                require_relative '../../../../bin/migrate'

                assert Sequel::Database.method_defined?(:safe_migration_wrapper)

                Process.exit!(0)
              end

            Process.waitpid(pid)
            assert $CHILD_STATUS.success?
          end
        end
      end

which is now failing with:

Minitest::UnexpectedError:         NoMethodError: undefined method `[]' for nil:NilClass
            /home/affinity/test/sequel/extensions/robust_migrations/sequel_robust_migrations_enabled_test.rb:15:in `fork'
            /home/affinity/test/sequel/extensions/robust_migrations/sequel_robust_migrations_enabled_test.rb:15:in `block (2 levels) in <class:SequelRobustMigrationsEnabledTest>'

[casperisfine]

@mscrivo sequel doesn't depend on connection_pool.

Try to remove whatever backtrace cleaner you have, I highly suspect this is from net-http-persistent.

[mscrivo]

@mscrivo sequel doesn't depend on connection_pool. Try to remove whatever backtrace cleaner you have, I highly suspect this is from net-http-persistent.

Ah ok that makes sense, will wait for an update to that gem as well .. thanks!

[casperisfine]

net-http-persistent 4.0.2 is out.