ActiveRecord::ConnectionTimeoutError: could not obtain a database connection within 5.000 seconds (waited 5.000 seconds)

Question

I have a rails app in production that i deployed some changes to the other day. All of a sudden now I get the error ActiveRecord::ConnectionTimeoutError: could not obtain a database connection within 5.000 seconds (waited 5.000 seconds) multiple times a day and have to restart puma to fix the issue.

I'm completely stumped as to what is causing this. I didn't change anything on my server and the changes I made were pretty simple (add to a view and add to a controller method).

I'm not seeing much of anything in the log files.

I'm using rails 4.1.4 and ruby 2.0.0p481

Any ideas as to why my connections are filling up? My connection pool is set to 10 and i'm using the default puma configuration.

Here's a stack trace:

ActiveRecord::ConnectionTimeoutError (could not obtain a database connection within 5.000 seconds (waited 5.000 seconds)):
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `block in wait_poll'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `loop'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `wait_poll'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:136:in `block in poll'
  /usr/local/rvm/rubies/ruby-2.0.0-p481/lib/ruby/2.0.0/monitor.rb:211:in `mon_synchronize'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:146:in `synchronize'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:134:in `poll'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:418:in `acquire_connection'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:351:in `block in checkout'
  /usr/local/rvm/rubies/ruby-2.0.0-p481/lib/ruby/2.0.0/monitor.rb:211:in `mon_synchronize'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:350:in `checkout'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:265:in `block in connection'
  /usr/local/rvm/rubies/ruby-2.0.0-p481/lib/ruby/2.0.0/monitor.rb:211:in `mon_synchronize'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:264:in `connection'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:541:in `retrieve_connection'
  activerecord (4.1.4) lib/active_record/connection_handling.rb:113:in `retrieve_connection'
  activerecord (4.1.4) lib/active_record/connection_handling.rb:87:in `connection'
  activerecord (4.1.4) lib/active_record/query_cache.rb:51:in `restore_query_cache_settings'
  activerecord (4.1.4) lib/active_record/query_cache.rb:43:in `rescue in call'
  activerecord (4.1.4) lib/active_record/query_cache.rb:32:in `call'
  activerecord (4.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:621:in `call'
  actionpack (4.1.4) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (4.1.4) lib/active_support/callbacks.rb:82:in `run_callbacks'
  actionpack (4.1.4) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (4.1.4) lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
  airbrake (4.1.0) lib/airbrake/rails/middleware.rb:13:in `call'
  actionpack (4.1.4) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
  actionpack (4.1.4) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  railties (4.1.4) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.1.4) lib/rails/rack/logger.rb:20:in `block in call'
  activesupport (4.1.4) lib/active_support/tagged_logging.rb:68:in `block in tagged'
  activesupport (4.1.4) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (4.1.4) lib/active_support/tagged_logging.rb:68:in `tagged'
  railties (4.1.4) lib/rails/rack/logger.rb:20:in `call'
  actionpack (4.1.4) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.5.2) lib/rack/methodoverride.rb:21:in `call'
  dragonfly (1.0.5) lib/dragonfly/cookie_monster.rb:9:in `call'
  rack (1.5.2) lib/rack/runtime.rb:17:in `call'
  activesupport (4.1.4) lib/active_support/cache/strategy/local_cache_middleware.rb:26:in `call'
  rack (1.5.2) lib/rack/sendfile.rb:112:in `call'
  airbrake (4.1.0) lib/airbrake/user_informer.rb:16:in `_call'
  airbrake (4.1.0) lib/airbrake/user_informer.rb:12:in `call'
  railties (4.1.4) lib/rails/engine.rb:514:in `call'
  railties (4.1.4) lib/rails/application.rb:144:in `call'
  railties (4.1.4) lib/rails/railtie.rb:194:in `public_send'
  railties (4.1.4) lib/rails/railtie.rb:194:in `method_missing'
  puma (2.9.0) lib/puma/configuration.rb:71:in `call'
  puma (2.9.0) lib/puma/server.rb:490:in `handle_request'
  puma (2.9.0) lib/puma/server.rb:361:in `process_client'
  puma (2.9.0) lib/puma/server.rb:254:in `block in run'
  puma (2.9.0) lib/puma/thread_pool.rb:92:in `call'
  puma (2.9.0) lib/puma/thread_pool.rb:92:in `block in spawn_thread'

Puma init.d script

#!/bin/sh
# Starts and stops puma
#


case "$1" in
        start)
                su myuser -c  "source /etc/profile && cd /var/www/myapp/current && rvm gemset use myapp && puma -d -e production -b unix:///var/www/myapp/myapp_app.sock -S /var/www/myapp/myapp_app.state"
        ;;

        stop)
                su myuser -c "source /etc/profile && cd /var/www/myapp/current &&  rvm gemset use myapp && RAILS_ENV=production bundle exec pumactl -S /var/www/myapp/myapp_app.state stop"
        ;;

        restart)
                $0 stop
                $0 start
        ;;

        *)
                echo "Usage: $0 {start|stop|restart}"
                exit 1
esac

EDIT

I think i've finally narrowed down the issue to be with the airbrake gem and using the devise method current_user or user_signed_in? in application_controller.rb in a before_action.

Here's my application controller:

class ApplicationController < ActionController::Base
  protect_from_forgery
  before_filter :authenticate_user!, :get_new_messages 

  # Gets the unread messages for the logged in user
  def get_new_messages
    @num_new_messages = 0 # Initially set to 0 so login page, etc works
    # If the user is signed in, fetch the new messages
    if user_signed_in? # I also tried !current_user.nil?
      @num_new_messages = Message.where(:created_for => current_user.id).where(:viewed => false).count
    end
  end

...
end

If i remove the if block, i have no problems. Since i introduced that code, my app seems to run out of connections. If i leave that if block in place and remove the airbrake gem, my app seems to run just fine with only the default 5 connections set on my pool in my database.yml file.

EDIT

I finally figure out that if I comment out this line in my config/environments/production.rb file config.exceptions_app = self.routes that I don't get the error. It seems that custom routes + devise in the app controller before_action are the cause. I've created an issue and a reproducable project on github.

https://github.com/plataformatec/devise/issues/3422 https://github.com/toymachiner62/devise-connection-failure/blob/master/config/environments/production.rb#L84

Malinin

Is this relevant? #24912338 – Ryeland

It could be relevant but the weird thing is that I haven't had any problems like this for a year and i've deployed changes throughout the last year. The other day is the first time i've had this issue. – Malinin

How many Puma threads are you running? Also, do you have workers(sidekiq, delayedJob, etc.)? – Sustentation

No workers. I'm running just 1 puma thread i believe. I'm just using the default puma config. – Malinin

Can you increase your DB pool size? Does that reduce or stop the timeouts? – Sustentation

Will this help u. devcenter.heroku.com/articles/… – Philomenaphiloo

I've tried increasing it to 30 and it still eventually runs out of connections. – Malinin

What DB are you using? Can you connect to this DB using the rails app credentials from the command line? – Arnaud

I'm using mysql. Even when my app cannot get a connection, I can connect directly to mysql using an external sql client and the command line. – Malinin

Are you running a lengthy query that is causing the connections to timeout? Are you running NewRelic? – Sustentation

Does this happen on development with WEBrick too? I'm getting this too on develop... Will add to your bounty if you can let me know. @eabraham, why do you mention NewRelic? I'm running that – Babblement

I've not been able to recreate this in dev. I've narrowed it down to using a devuse method (current_user or user_signed_in?) in a before filter in my application controller. – Malinin

Answer 1

With the help of the devise guys' I think I finally got this issue figured out. It seemed that by using custom error pages with it's own controller, I wasn't skipping the before_action get_new_messages. So the very simple fix was to add:

skip_before_filter :get_new_messages

to my custom error controller.

This issue explains in detail the reason behind this: https://github.com/plataformatec/devise/issues/3422

Malinin

Answer 2

I had the same problems which were caused by too many open connections to the database. This can happen when you have database queries outside of a controller (in a model, mailer, pdf generator, ...).

I could fix it by wrapping those queries in this block which closes the connection automatically.

ActiveRecord::Base.connection_pool.with_connection do
  # your code
end

Since Puma works multi-threaded, the pool size (as eabraham mentioned) can be a limitation, too. Try to increase it (a little)...

I hope this helps!

Shirk

Answer 3

Ultimately this issue still plagued me for another year or so. I finally got a good solution from working with the puma guys.

Upgrade your puma to at least 2.15.x.

Malinin

the issue still persists. What ruby and puma versions are you on right now? I'm on JRuby 9.1.2.0 and puma 3.4.0. – Freewheel

I'm stil on puma 2.15.x and I'm running MRI version of Ruby i believe. Definitely not on JRuby. Probably version 2.1.x or 2.2.x. – Malinin

@bibstha There is no issue with latest Puma. I was getting the error due to improper use of concurrent-ruby. This Post helped me. – Freewheel