Using Phusion Passenger / Forking on Rails 5.2: NoMethodError (undefined method `any?' for nil:NilClass)

[erkie]

While trying to deploy our fork we got another error message when deploying to Phusion Passenger.

NoMethodError (undefined method `any?' for nil:NilClass):

activerecord (5.2.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:421:in `block in connected?'
/Users/erik/.rvm/rubies/ruby-2.5.1/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
activerecord (5.2.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:421:in `connected?'
/Users/erik/feederco/octopus/lib/octopus/proxy.rb:165:in `block in connected?'
/Users/erik/feederco/octopus/lib/octopus/proxy.rb:165:in `any?'
/Users/erik/feederco/octopus/lib/octopus/proxy.rb:165:in `connected?'
/Users/erik/feederco/octopus/lib/octopus/model.rb:202:in `connected_with_octopus?'
activerecord (5.2.0) lib/active_record/railtie.rb:163:in `block (3 levels) in <class:Railtie>'

This could easiliy be replicated locally by downloading and running Passenger Standalone

passenger start --port 3001

It seems to be related to this commit:

https://github.com/rails/rails/commit/f32cff5563f2188e657aa2fd9f8513f0da4a49ca#diff-7735c67f539e7d1e2908a4d5d8909c24R453

From what I can read from there it seems that it is no longer safe to use ConnectionPool after it has been discarded.

[thiagopradi]

Hi @erkie - can you try to use Octopus from this PR (https://github.com/thiagopradi/octopus/pull/494) and see if that fixes your issue? thanks.

[erkie]

Hi, sorry! We moved to Knockoff briefly after I made this issue, but I still think the steps should work by using passenger start --port 3001

[whitmer]

Seeing a similar issue but with Puma:

NoMethodError (undefined method `any?' for nil:NilClass):

activerecord (5.2.2) lib/active_record/connection_adapters/abstract/connection_pool.rb:423:in `block in connected?'
/Users/whitmer/.rvm/rubies/ruby-2.5.3/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
activerecord (5.2.2) lib/active_record/connection_adapters/abstract/connection_pool.rb:423:in `connected?'
ar-octopus (0.10.1) lib/octopus/proxy.rb:73:in `safe_connection'
ar-octopus (0.10.1) lib/octopus/proxy.rb:81:in `select_connection'
ar-octopus (0.10.1) lib/octopus/proxy.rb:226:in `legacy_method_missing_logic'
ar-octopus (0.10.1) lib/octopus/proxy.rb:132:in `method_missing'
activerecord (5.2.2) lib/active_record/migration.rb:554:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
activesupport (5.2.2) lib/active_support/callbacks.rb:98:in `run_callbacks'
actionpack (5.2.2) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/executor.rb:14:in `call'
bugsnag (6.10.0) lib/bugsnag/integrations/rack.rb:46:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
railties (5.2.2) lib/rails/rack/logger.rb:38:in `call_app'
railties (5.2.2) lib/rails/rack/logger.rb:26:in `block in call'
activesupport (5.2.2) lib/active_support/tagged_logging.rb:71:in `block in tagged'
activesupport (5.2.2) lib/active_support/tagged_logging.rb:28:in `tagged'
activesupport (5.2.2) lib/active_support/tagged_logging.rb:71:in `tagged'
railties (5.2.2) lib/rails/rack/logger.rb:26:in `call'
silencer (1.0.1) lib/silencer/rails/logger.rb:41:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
request_store (1.4.1) lib/request_store/middleware.rb:19:in `call'
rack-timeout (0.5.1) lib/rack/timeout/core.rb:123:in `block in call'
rack-timeout (0.5.1) lib/rack/timeout/support/timeout.rb:19:in `timeout'
rack-timeout (0.5.1) lib/rack/timeout/core.rb:122:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/request_id.rb:27:in `call'
rack (2.0.6) lib/rack/method_override.rb:22:in `call'
rack (2.0.6) lib/rack/runtime.rb:22:in `call'
rack-timeout (0.5.1) lib/rack/timeout/core.rb:123:in `block in call'
rack-timeout (0.5.1) lib/rack/timeout/support/timeout.rb:19:in `timeout'
rack-timeout (0.5.1) lib/rack/timeout/core.rb:122:in `call'
activesupport (5.2.2) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.2) lib/action_dispatch/middleware/static.rb:127:in `call'
rack (2.0.6) lib/rack/sendfile.rb:111:in `call'
railties (5.2.2) lib/rails/engine.rb:524:in `call'
puma (3.12.0) lib/puma/configuration.rb:225:in `call'
puma (3.12.0) lib/puma/server.rb:658:in `handle_request'
puma (3.12.0) lib/puma/server.rb:472:in `process_client'
puma (3.12.0) lib/puma/server.rb:332:in `block in run'
puma (3.12.0) lib/puma/thread_pool.rb:133:in `block in spawn_thread'

The connection_pool is getting discarded as part of the puma forking process, though I'm not smart enough to figure out if that's the root issue or if something else is going on:

/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:465:in `discard!'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:932:in `each'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:932:in `block in discard_unowned_pools'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/concurrent-ruby-1.1.3/lib/concurrent/collection/map/non_concurrent_map_backend.rb:99:in `block in each_pair'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/concurrent-ruby-1.1.3/lib/concurrent/collection/map/non_concurrent_map_backend.rb:98:in `each_pair'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/concurrent-ruby-1.1.3/lib/concurrent/collection/map/non_concurrent_map_backend.rb:98:in `each_pair'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/concurrent-ruby-1.1.3/lib/concurrent/map.rb:262:in `each_pair'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:931:in `discard_unowned_pools'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:941:in `block in initialize'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/concurrent-ruby-1.1.3/lib/concurrent/map.rb:140:in `[]'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:1061:in `owner_to_pool'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:1031:in `remove_connection'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:960:in `establish_connection'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/activerecord-5.2.2/lib/active_record/connection_handling.rb:60:in `establish_connection'
config/puma.rb:16:in `block in _load_from'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/configuration.rb:276:in `block in run_hooks'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/configuration.rb:276:in `each'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/configuration.rb:276:in `run_hooks'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:271:in `worker'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:137:in `block (2 levels) in spawn_workers'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:137:in `fork'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:137:in `block in spawn_workers'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:133:in `times'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:133:in `spawn_workers'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cluster.rb:466:in `run'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/launcher.rb:184:in `run'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/lib/puma/cli.rb:78:in `run'
/Users/whitmer/.rvm/gems/ruby-2.5.3/gems/puma-3.12.0/bin/puma:10:in `<top (required)>'
/Users/whitmer/.rvm/gems/ruby-2.5.3/bin/puma:23:in `load'
/Users/whitmer/.rvm/gems/ruby-2.5.3/bin/puma:23:in `<main>'
/Users/whitmer/.rvm/gems/ruby-2.5.3/bin/ruby_executable_hooks:24:in `eval'
/Users/whitmer/.rvm/gems/ruby-2.5.3/bin/ruby_executable_hooks:24:in `<main>'

puma has on_worker_boot which is where you're supposed to put your setup code, but discard is getting called after that boot block is executed.

I was actually seeing an issue on Rails >= 5.0.1 < 5.2 where the db would run out of available connections, now I'm wondering if that's related. Had to revert back to Rails 5.0.0 for production for now.

[jhoareau]

I'm experiencing the same issue as @whitmer with the latest version of the gem (0.10.1) and Rails 5.2, using Puma forked workers. I've written a terrible money-patch hack/workaround that seems to do the trick on most requests except some edge cases on non-preheated workers, in config/initializers/octopus.rb :

module Octopus
  class Proxy
    alias_method :safe_connection_without_fork_check, :safe_connection

    def safe_connection_with_fork_check(connection_pool)
      safe_connection_without_fork_check(connection_pool)
    rescue NoMethodError
      proxy_config.reinitialize_shards
      retry
    end

    alias_method :safe_connection, :safe_connection_with_fork_check

    def connected?
      shards.any? { |_k, v| v.connected? }
    rescue NoMethodError
      proxy_config.reinitialize_shards
      retry
    end
  end
end

[zainzafar]

I'm also facing the same issue as @whitmer and @jhoareau.

@jhoareau I tried using your Monkey Patch but doesn't work either. I get an error saying that Resource temporarily unavailable.

My environment: Rails 5.2.2 Octopus: 0.10.1 Puma 3.12.0

[kjvarga]

@jhoareau I've been running with the Octopus work around you mentioned above and it was pretty good. But my Sidekiq worker nodes sometimes become unresponsive and out of memory. So I tried your Puma on_worker_boot work around but started receiving RuntimeError: Nonexistent Shard Name: master errors from my endpoints (and the workers - sometimes). I don't think our code is at fault because we don't refer explicitly to the master shard (I've read about string/symbol issues for the shard names). And now I can't find your Puma workaround - has the comment been deleted?

[jhoareau]

I guess you should replace the retry with a finite retry (a few times at most then throw the exception) :) And the Puma workaround didn't help at all in the end.

[sagar18041]

Similar issue with Unicorn on production environment: NoMethodError (undefined methodany?' for nil:NilClass): F, [2019-02-07T09:54:30.989707 #5893] FATAL -- :
F, [2019-02-07T09:54:30.989764 #5893] FATAL -- : activerecord (5.2.2) lib/active_record/connection_adapters/abstract/connection_pool.rb:423:in block in connected?' /usr/local/rvm/rubies/ruby-2.5.3/lib/ruby/2.5.0/monitor.rb:226:inmon_synchronize' activerecord (5.2.2) lib/active_record/connection_adapters/abstract/connection_pool.rb:423:in connected?' ar-octopus (0.10.1) lib/octopus/proxy.rb:173:inblock in connected?' ar-octopus (0.10.1) lib/octopus/proxy.rb:173:in any?' ar-octopus (0.10.1) lib/octopus/proxy.rb:173:inconnected?' ar-octopus (0.10.1) lib/octopus/model.rb:194:in connected_with_octopus?' activerecord (5.2.2) lib/active_record/railties/controller_runtime.rb:42:inappend_info_to_payload' actionpack (5.2.2) lib/action_controller/metal/instrumentation.rb:38:in ensure in block in process_action' actionpack (5.2.2) lib/action_controller/metal/instrumentation.rb:38:inblock in process_action' activesupport (5.2.2) lib/active_support/notifications.rb:168:in block in instrument' activesupport (5.2.2) lib/active_support/notifications/instrumenter.rb:23:ininstrument' activesupport (5.2.2) lib/active_support/notifications.rb:168:in instrument' actionpack (5.2.2) lib/action_controller/metal/instrumentation.rb:32:inprocess_action' actionpack (5.2.2) lib/action_controller/metal/params_wrapper.rb:256:in process_action' searchkick (3.1.2) lib/searchkick/logging.rb:209:inprocess_action' activerecord (5.2.2) lib/active_record/railties/controller_runtime.rb:24:in process_action' actionpack (5.2.2) lib/abstract_controller/base.rb:134:inprocess' actionpack (5.2.2) lib/action_controller/metal.rb:191:in dispatch' actionpack (5.2.2) lib/action_controller/metal.rb:252:indispatch' actionpack (5.2.2) lib/action_dispatch/routing/route_set.rb:52:in dispatch' actionpack (5.2.2) lib/action_dispatch/routing/route_set.rb:34:inserve' actionpack (5.2.2) lib/action_dispatch/journey/router.rb:52:in block in serve' actionpack (5.2.2) lib/action_dispatch/journey/router.rb:35:ineach' actionpack (5.2.2) lib/action_dispatch/journey/router.rb:35:in serve' actionpack (5.2.2) lib/action_dispatch/routing/route_set.rb:840:incall' warden (1.2.8) lib/warden/manager.rb:36:in block in call' warden (1.2.8) lib/warden/manager.rb:34:incatch' warden (1.2.8) lib/warden/manager.rb:34:in call' rack (2.0.6) lib/rack/etag.rb:25:incall' rack (2.0.6) lib/rack/conditional_get.rb:25:in call' rack (2.0.6) lib/rack/head.rb:12:incall' actionpack (5.2.2) lib/action_dispatch/middleware/callbacks.rb:28:in block in call' activesupport (5.2.2) lib/active_support/callbacks.rb:98:inrun_callbacks' actionpack (5.2.2) lib/action_dispatch/middleware/callbacks.rb:26:in call' actionpack (5.2.2) lib/action_dispatch/middleware/debug_exceptions.rb:61:incall' actionpack (5.2.2) lib/action_dispatch/middleware/show_exceptions.rb:33:in call' railties (5.2.2) lib/rails/rack/logger.rb:38:incall_app' railties (5.2.2) lib/rails/rack/logger.rb:26:in block in call' activesupport (5.2.2) lib/active_support/tagged_logging.rb:71:inblock in tagged' activesupport (5.2.2) lib/active_support/tagged_logging.rb:28:in tagged' activesupport (5.2.2) lib/active_support/tagged_logging.rb:71:intagged' railties (5.2.2) lib/rails/rack/logger.rb:26:in call' actionpack (5.2.2) lib/action_dispatch/middleware/remote_ip.rb:81:incall' request_store (1.4.1) lib/request_store/middleware.rb:19:in call' actionpack (5.2.2) lib/action_dispatch/middleware/request_id.rb:27:incall' rack (2.0.6) lib/rack/runtime.rb:22:in call' activesupport (5.2.2) lib/active_support/cache/strategy/local_cache_middleware.rb:29:incall' actionpack (5.2.2) lib/action_dispatch/middleware/executor.rb:14:in call' rack (2.0.6) lib/rack/sendfile.rb:111:incall' rack-cors (1.0.2) lib/rack/cors.rb:97:in call' railties (5.2.2) lib/rails/engine.rb:524:incall' unicorn (5.4.1) lib/unicorn/http_server.rb:606:in process_client' unicorn (5.4.1) lib/unicorn/http_server.rb:701:inworker_loop' unicorn (5.4.1) lib/unicorn/http_server.rb:549:in spawn_missing_workers' unicorn (5.4.1) lib/unicorn/http_server.rb:142:instart' unicorn (5.4.1) bin/unicorn:126:in <top (required)>' /usr/local/rvm/gems/ruby-2.5.3@rails_app-service/bin/unicorn:23:inload' /usr/local/rvm/gems/ruby-2.5.3@rails_app-service/bin/unicorn:23:in <main>' /usr/local/rvm/gems/ruby-2.5.3@rails_app-service/bin/ruby_executable_hooks:24:ineval' /usr/local/rvm/gems/ruby-2.5.3@rails_app-service/bin/ruby_executable_hooks:24:in <main>' Version: Rails 5.2.2 Ruby 2.5.3 Octopus 0.10.1 Unicorn 5.4.1

[knagode]

I am getting this error as well. We are using puma. I noticed that everything works in console (rails c).

[taf2]

I can say for sure that this error is directly related to mis-configured database connection handling in your puma / unicorn configuration... Be sure you are correctly disconnect in your before fork and also reconnecting correctly in your after fork.

For example unicorn you need before fork:

      ActiveRecord::Base.connection_proxy.clear_all_connections!
      # maybe also any pools
      (ActiveRecord::Base.connection_proxy.instance_variable_get(:@shards) || []).each do |shard, connection_pool|
        connection_pool.disconnect!
      end

after fork

    Octopus.config['production']['master'] = ActiveRecord::Base.connection.config # maybe needed 
    ActiveRecord::Base.connection.initialize_shards(Octopus.config)