I´m getting this severe error in my Rails 4 app and because of that my connection to my database is lost.
F, [2015-12-23T18:06:22.875935 #13919] FATAL -- :
ActiveRecord::ConnectionTimeoutError (could not obtain a database connection within 5.000 seconds (waited 5.009 seconds)):
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `block in wait_poll'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `loop'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `wait_poll'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:136:in `block in poll'
/home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:146:in `synchronize'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:134:in `poll'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:423:in `acquire_connection'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:356:in `block in checkout'
/home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:355:in `checkout'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:265:in `block in connection'
/home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:264:in `connection'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:546:in `retrieve_connection'
activerecord (4.0.0) lib/active_record/connection_handling.rb:79:in `retrieve_connection'
activerecord (4.0.0) lib/active_record/connection_handling.rb:53:in `connection'
activerecord (4.0.0) lib/active_record/query_cache.rb:51:in `restore_query_cache_settings'
activerecord (4.0.0) lib/active_record/query_cache.rb:43:in `rescue in call'
activerecord (4.0.0) lib/active_record/query_cache.rb:32:in `call'
activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:626:in `call'
actionpack (4.0.0) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
activesupport (4.0.0) lib/active_support/callbacks.rb:373:in `_run__285615481658568074__call__callbacks'
activesupport (4.0.0) lib/active_support/callbacks.rb:80:in `run_callbacks'
actionpack (4.0.0) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
actionpack (4.0.0) lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
actionpack (4.0.0) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
actionpack (4.0.0) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
railties (4.0.0) lib/rails/rack/logger.rb:38:in `call_app'
railties (4.0.0) lib/rails/rack/logger.rb:21:in `block in call'
activesupport (4.0.0) lib/active_support/tagged_logging.rb:67:in `block in tagged'
activesupport (4.0.0) lib/active_support/tagged_logging.rb:25:in `tagged'
activesupport (4.0.0) lib/active_support/tagged_logging.rb:67:in `tagged'
railties (4.0.0) lib/rails/rack/logger.rb:21:in `call'
actionpack (4.0.0) lib/action_dispatch/middleware/request_id.rb:21:in `call'
rack (1.5.2) lib/rack/methodoverride.rb:21:in `call'
rack (1.5.2) lib/rack/runtime.rb:17:in `call'
activesupport (4.0.0) lib/active_support/cache/strategy/local_cache.rb:83:in `call'
railties (4.0.0) lib/rails/engine.rb:511:in `call'
railties (4.0.0) lib/rails/application.rb:97:in `call'
puma (2.10.1) lib/puma/configuration.rb:74:in `call'
puma (2.10.1) lib/puma/server.rb:490:in `handle_request'
puma (2.10.1) lib/puma/server.rb:361:in `process_client'
puma (2.10.1) lib/puma/server.rb:254:in `block in run'
puma (2.10.1) lib/puma/thread_pool.rb:96:in `call'
puma (2.10.1) lib/puma/thread_pool.rb:96:in `block in spawn_thread'
I´m trying to debug it but it´s quite complex. I don´t know where the issue is coming from.
I read this post before ActiveRecord::ConnectionTimeoutError: could not obtain a database connection within 5.000 seconds (waited 5.000 seconds) and there is an answer from @railsana that fits one possible scenario of mine.
I have some kind of batch processes that makes lots of queries called from a model (outside controller) by an scheduled task. I tried to follow their suggestion and added this code to this functionality, however the issue is still there.
ActiveRecord::Base.connection_pool.with_connection do
# your code
end
Just in case it´s a relevant information, my rails app is running in a Puma server and my database is MySQL.
Any suggestions, what can it be, or how to debug it? The bug is really fatal because my application cannot handle any query.
UPDATE: Answering to the questions: 1. In production I have configured a pool with 5 connections in config/database.yml. 2. My Puma server startup log:
Puma starting in single mode...
* Version 2.10.1 (ruby 2.1.2-p95), codename: Robots on Comets
* Min threads: 0, max threads: 16
* Environment: production
* Daemonizing..
.
Only one worker is started.
UPDATE 2:
Checking puma.stderr.log I found this kind of error logs:
{ 70238458077400 rufus-scheduler intercepted an error:
70238458077400 job:
70238458077400 Rufus::Scheduler::EveryJob "90s" {}
70238458077400 error:
70238458077400 70238458077400
70238458077400 Net::ReadTimeout
70238458077400 Net::ReadTimeout
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:158:in `rescue in rbuf_fill'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:152:in `rbuf_fill'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:134:in `readuntil'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:144:in `readline'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http/response.rb:39:in `read_status_line'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http/response.rb:28:in `read_new'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1408:in `block in transport_request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1405:in `catch'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1405:in `transport_request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1378:in `request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rest-client-1.6.7/lib/restclient/net_http_ext.rb:51:in `request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:65:in `perform'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:42:in `block in request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:78:in `call'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:78:in `block in do_request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:853:in `start'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:76:in `do_request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:33:in `request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi.rb:161:in `request'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi.rb:133:in `post'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/operation.rb:94:in `block in call_with_logging'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/request_logger.rb:12:in `call'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/request_logger.rb:12:in `log'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/operation.rb:94:in `call_with_logging'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/operation.rb:54:in `call'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/client.rb:36:in `call'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:560:in `block (2 levels) in getAvailabilities'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:544:in `each'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:544:in `block in getAvailabilities'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activerecord-4.0.0/lib/active_record/relation/delegation.rb:13:in `each'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activerecord-4.0.0/lib/active_record/relation/delegation.rb:13:in `each'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:530:in `getAvailabilities'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:65:in `updateAvailabilities'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/app/models/secretary.rb:182:in `block in getBoatsAvailability'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activerecord-4.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:294:in `with_connection'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/app/models/secretary.rb:181:in `getBoatsAvailability'
70238458077400 /home/ubuntu/env/production/www/yanpyapi/config/initializers/task_scheduler.rb:29:in `block in <top (required)>'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `call'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `do_trigger'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:269:in `block (3 levels) in start_work_thread'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `call'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `block (2 levels) in start_work_thread'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `loop'
70238458077400 /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `block in start_work_thread'
} 70238458077400 .
This is the portion of code that is sending throwing this exception (I think not catched exception):
# This method is in a model invoked by an scheduled task rufus-scheduler that is executed every 90 seconds.
def self.getBoatsAvailability
if Rails.env.production?
require 'service'
# This line was added to try to fix this problem (I read this approach in another post link above)
ActiveRecord::Base.connection_pool.with_connection do
Service.getAvailabilities(false)
end
end
end
def self.getAvailabilities(isMonthly)
@logger.debug "Importing availabilities..."
# Savon is a service to communicate with SOAP web services
client = Savon.client(wsdl: "url",
log_level: :debug,
log: true,
pretty_print_xml: true)
mmkCompanies = Mmk::Company.select("id").where(loading: true).order("id")
createdAt = Time.now
@logger.debug "getAvailabilities Before each company."
for mmkCompany in mmkCompanies do
lastModifiedReq = Mmk::Availability.find_by_sql(["SELECT max(a.created_at) as max_date
FROM mmk_availabilities a, mmk_resources r
WHERE a.resource_id = r.id
AND r.company_id = ?", mmkCompany.id]).first.max_date
(0..1).each do |i|
year = Time.now.year + i
message = {'in0' => credentials,
'in1' => credentials,
'in2' => credentials,
'in3' => mmkCompany.id,
'in4' => year,
'in5' => true,
'in6' => lastModifiedReq}
@logger.debug "getAvailabilities Before client call."
response = client.call(:get_availability_info, message: message)
@logger.debug "getAvailabilities After client call."
availabilitiesXML = response.to_hash[:get_availability_info_response][:out]
availabilitiesParsed = Nokogiri::XML(availabilitiesXML)
availabilities = availabilitiesParsed.xpath("//reservation")
@logger.debug "getAvailabilities Before transaction."
Mmk::Availability.transaction do
@logger.debug "getAvailabilities Transaction opened."
for availability in availabilities do
id = availability["id"]
# More parse parameters unrelevant code
mmkAvailability = Mmk::Availability.find_or_initialize_by(id: id)
mmkAvailability.update(resource_id: resourceId, status: status, blocks_availability: blocksAvailability,
date_from: dateFrom, date_to: dateTo, base_from: baseFrom, base_to: baseTo,
option_expiry_date: optionExpiryDate, last_modified: lastModified, created_at: createdAt)
mmkAvailability.save
end
end
@logger.debug "getAvailabilities After transaction (closed)?."
end
end
@logger.debug "Availability imported successfully."
end
This line in exception:
`70238458077400 /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:560:in `block (2 levels) in getAvailabilities'`
correspondes to:
response = client.call(:get_availability_info, message: message)
My analysis (althouth not everything is matching for me), is: - The method getAvailabilities is sending a webservice SOAP request to a third party system. - Sometimes for some reason, this connection is lost or the third party service doesn´t response and Net::ReadTimeout exception is thrown. - This exception is not caught. And a database connection (and this is the part I don´t understand) keeps opened. - When this issue happens 5 times, the number of pool connections is 0 and I got the main issue.
