ActiveRecord::ConnectionTimeoutError on GET /favicon.ico

Hey,

recently I started getting ConnectionTimeoutError on initial /favicon.ico request during my development. If I read the stacktrace correctly, it looks like that some middleware is trying to do DB request while serving a static file. This smells, because it is likely doing database access on each request.

app|I Started GET "/" for 127.0.0.1 at 2018-05-04 11:31:35 +0200
app|F   
app|F ActiveRecord::ConnectionTimeoutError (could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use):
app|F   
app|F activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:202:in `block in wait_poll'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'
 | /home/lzap/.rbenv/versions/2.5.1/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:747:in `acquire_connection'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:500:in `checkout'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:374:in `connection'
 | activerecord (5.1.4) lib/active_record/connection_adapters/abstract/connection_pool.rb:931:in `retrieve_connection'
 | activerecord (5.1.4) lib/active_record/connection_handling.rb:116:in `retrieve_connection'
 | activerecord (5.1.4) lib/active_record/connection_handling.rb:88:in `connection'
 | activerecord (5.1.4) lib/active_record/migration.rb:562:in `connection'
 | activerecord (5.1.4) lib/active_record/migration.rb:553:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
 | activesupport (5.1.4) lib/active_support/callbacks.rb:97:in `run_callbacks'
 | actionpack (5.1.4) lib/action_dispatch/middleware/callbacks.rb:24:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/executor.rb:12:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
 | railties (5.1.4) lib/rails/rack/logger.rb:36:in `call_app'
 | railties (5.1.4) lib/rails/rack/logger.rb:26:in `call'
 | sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/request_id.rb:25:in `call'
 | rack (2.0.5) lib/rack/method_override.rb:22:in `call'
 | rack (2.0.5) lib/rack/runtime.rb:22:in `call'
 | activesupport (5.1.4) lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/executor.rb:12:in `call'
 | actionpack (5.1.4) lib/action_dispatch/middleware/static.rb:125:in `call'
 | rack (2.0.5) lib/rack/sendfile.rb:111:in `call'
 | secure_headers (5.0.5) lib/secure_headers/middleware.rb:13:in `call'
 | railties (5.1.4) lib/rails/engine.rb:522:in `call'
 | railties (5.1.4) lib/rails/railtie.rb:185:in `public_send'
 | railties (5.1.4) lib/rails/railtie.rb:185:in `method_missing'
 | rack (2.0.5) lib/rack/urlmap.rb:68:in `block in call'
 | rack (2.0.5) lib/rack/urlmap.rb:53:in `each'
 | rack (2.0.5) lib/rack/urlmap.rb:53:in `call'
 | rack (2.0.5) lib/rack/handler/webrick.rb:86:in `service'
 | /home/lzap/.rbenv/versions/2.5.1/lib/ruby/2.5.0/webrick/httpserver.rb:140:in `service'
 | /home/lzap/.rbenv/versions/2.5.1/lib/ruby/2.5.0/webrick/httpserver.rb:96:in `run'
 | /home/lzap/.rbenv/versions/2.5.1/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'
 | logging (2.2.2) lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
app|I   Rendered /home/lzap/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/templates/rescues/diagnostics.html.erb within rescues/layout (14.2ms)
127.0.0.1 - - [04/May/2018:11:31:35 CEST] "GET / HTTP/1.1" 500 59886

And it’s not just favicon.ico but I am getting many of these timeout errors when there are concurrent requests. It used to work just fine. I have sqlite3 database.

Any ideas?

Could this be caused by the MigrationChecker being called?

Good idea, does not seem to be this one tho, tried to do some debug statements and it runs afterwards.

About other timeout errors, it looks like db pool setting of 5 (default value) is not enough for our dashboard. Rails 4 or 5 / webrick are now multithreaded by default and this creates some concurrency. Increasing this to 15 helped to get rid of these errors.

But why we do database call for a favicon.ico request still puzzles me.

Possibly checking for active session?