Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
erkie opened this issue Apr 17, 2018 · 10 comments

Comments

@erkie
Copy link
Contributor

@erkie erkie commented Apr 17, 2018

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:

rails/rails@f32cff5#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
Copy link
Owner

@thiagopradi thiagopradi commented Oct 16, 2018

Hi @erkie - can you try to use Octopus from this PR (#494) and see if that fixes your issue? thanks.

@erkie
Copy link
Contributor Author

@erkie erkie commented Oct 22, 2018

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
Copy link

@whitmer whitmer commented Dec 13, 2018

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
Copy link

@jhoareau jhoareau commented Jan 3, 2019

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
Copy link

@zainzafar zainzafar commented Jan 15, 2019

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.

screen shot 2019 01 15 at 3 09 51 pm

My environment:
Rails 5.2.2
Octopus: 0.10.1
Puma 3.12.0

@kjvarga
Copy link

@kjvarga kjvarga commented Jan 17, 2019

@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
Copy link

@jhoareau jhoareau commented Jan 17, 2019

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
Copy link

@sagar18041 sagar18041 commented Feb 7, 2019

Similar issue with Unicorn on production environment:
NoMethodError (undefined method any?' 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: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:173:in block in connected?'
ar-octopus (0.10.1) lib/octopus/proxy.rb:173:in any?' ar-octopus (0.10.1) lib/octopus/proxy.rb:173:in connected?'
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:in append_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:in block 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:in instrument'
activesupport (5.2.2) lib/active_support/notifications.rb:168:in instrument' actionpack (5.2.2) lib/action_controller/metal/instrumentation.rb:32:in process_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:in process_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:in process'
actionpack (5.2.2) lib/action_controller/metal.rb:191:in dispatch' actionpack (5.2.2) lib/action_controller/metal.rb:252:in dispatch'
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:in serve'
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:in each'
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:in call'
warden (1.2.8) lib/warden/manager.rb:36:in block in call' warden (1.2.8) lib/warden/manager.rb:34:in catch'
warden (1.2.8) lib/warden/manager.rb:34:in call' rack (2.0.6) lib/rack/etag.rb:25:in call'
rack (2.0.6) lib/rack/conditional_get.rb:25:in call' rack (2.0.6) lib/rack/head.rb:12: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/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' 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' actionpack (5.2.2) lib/action_dispatch/middleware/request_id.rb:27:in call'
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:in call'
actionpack (5.2.2) lib/action_dispatch/middleware/executor.rb:14:in call' rack (2.0.6) lib/rack/sendfile.rb:111:in call'
rack-cors (1.0.2) lib/rack/cors.rb:97:in call' railties (5.2.2) lib/rails/engine.rb:524:in call'
unicorn (5.4.1) lib/unicorn/http_server.rb:606:in process_client' unicorn (5.4.1) lib/unicorn/http_server.rb:701:in worker_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:in start'
unicorn (5.4.1) bin/unicorn:126:in <top (required)>' /usr/local/rvm/gems/ruby-2.5.3@rails_app-service/bin/unicorn:23:in load'
/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:in eval'
/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
Copy link

@knagode knagode commented Feb 18, 2019

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

@taf2
Copy link

@taf2 taf2 commented Feb 4, 2021

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)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants