Rails - erratic Timeout errors possibly tied to asset compilation

Question

Preemptive apologies for the code dump. I've been banging my head against this one for a while (and doing a ton of Googling) and just have a pretty fuzzy idea what is and isn't relevant, and how to fix things. So I figured I'd get as much info as possible out there. Please let me know if there's anything else I should add that might be helpful. Thanks!

I'm starting up a Rails and Angular app and mostly still in development mode. I'm using Heroku, but I don't know if these issues are serious there as well, cause I've mostly been coding and bumping into them on local (have barely poked around on production). (Just mentioned, because most similar questions seem to be Heroku-specific).

The error I keep intermittently bumping into is this one:

 Rack::Timeout::RequestTimeoutError: Request ran for longer than 5 seconds.

and its doppelganger:

 ActionView::Template::Error: Request ran for longer than 5 seconds.

When it's raised, it points to different files as the immediate culprit -- but always a Java/CoffeeScript or CSS/SASS file. Occasionally reloading the browser on the local server will pinwheel eternally instead of raising the above error. Often, a refresh will work fine, but occasionally I have to restart the server to "unfreeze" it.

I could try increasing the Rack::Timeout to something larger, but it strikes me that that would be treating one of potentially many symptoms, rather than the underlying problem.

I'm convinced this has something to do with an asset precompilation mistake of some sort -- which I'm new to, as this is my first serious app from scratch, particularly combining Angular and Rails.

I've had a hard time finding really smooth combinations of Rails and Angular -- advice is definitely appreciated.

I've managed to pinpoint the error by running and rerunning some feature specs while messing with my manifest SASS file. Every time I change the application.sass file by commenting some @imports out, (some of) the feature specs fail, but if I re-run them, they pass again and again, until I comment in or out a different line. The specific line(s) don't seem relevant, but, just in case I'm wrong, here's my application.sass file:

@charset "utf-8"

@import "bootstrap-sprockets"
@import "bootstrap"

@import "bourbon"
@import "base/grid-settings"
@import "neat"
@import "base/base"

@import "leaflet"

@import "skeleton/base"
@import "skeleton/layout"
@import "skeleton/skeleton"

@import "sections/header"
@import "sections/footer"
@import "sections/user"
@import "sections/map"
@import "sections/tabs"

@import "sections/baseapp"

@import "markercluster/MarkerCluster"
@import "markercluster/MarkerCluster.Default"

@import "icons"

@import "font-awesome-sprockets"
@import "font-awesome"

Because I think my messy asset solution is possibly to blame, I'll paste most of the relevant code below. Basically, I'm using NPM (package.json) for server-side JS stuff like Jasmine for testing, and Bower for client-side stuff like Angular and Leaflet (for maps). To make the Bower JS available in the Rails app, I'm using Rails Assets in my Gemfile. (Though I don't get why I need the bower.json stuff if I'm doing that). So the relevant parts of those manifest files look like this:

package.json

{
  "name": "whatever",
  "dependencies": {
    "rosie": "0.2.0",    
    "bower": "1.2.8",
    "jasmine": "2.1.1",
    "phantomjs": "1.9.13",
    "sinon": "1.12.2",
    "jasmine-sinon": "0.4.0",
    "requirejs": "2.1.15"
  },
  "devDependencies": {
    "grunt": "~0.4.4"
  }
}

bower.json

{
  "name": "whatever",
  "version": "0.1.0",
  "authors": [
    "Whatever"
  ],
  "ignore": [
    "**/.*",
    "node_modules",
    "bower_compnents",
    "test",
    "tests"
  ],
  "dependencies": {
    "angular": "latest",
    "angular-resource": "latest",
    "angular-route": "latest",
    "angular-mocks": "latest",
    "active-support": "latest",
    "async": "latest",
    "lodash": "latest",
    "leaflet": "latest",
    "leaflet.markercluster": "latest"
  }
}

I mean to tie down the versions before putting this in front of users.

Gemfile

gem 'rails-assets-angular'
gem 'rails-assets-angular-resource'
gem 'rails-assets-angular-route'
gem 'rails-assets-angular-mocks'
gem 'rails-assets-active-support'
gem 'rails-assets-async'
gem 'rails-assets-lodash'
gem 'rails-assets-leaflet'
gem 'rails-assets-requirejs'
gem 'rails-assets-sinon'
# gem 'rails-assets-leaflet.markercluster' -- wasn't working, so I included the relevant scripts in app/assets/javascripts/ -- seems to be working

I've also added these in the test group of my Gemfile. I'm worried about the overlap and sprawl of these JS inclusions, but this was what got the JS tests to work.

  gem "jasmine-rails"
  gem 'jasmine-headless-webkit'
  gem 'guard-jasmine'
  gem 'rails-assets-rosie'
  gem "sinon-rails"

I have a handful of assets I manually precompile for a variety of reasons:

config/initializers/assets.rb

Rails.application.config.assets.precompile += [ 
  'api/bookmarklets/view.js', 
  'sections/bookmarklet.css',   
  'icons.eot',
  'icons.svg',
  'icons.ttf',
  'icons.woff'
]

Locally, (and on production for now), my assets are just hosted on the server (so at localhost:3000). Doubt the DB is related, but its pool is set to 2 and timeout to 5000. Searching for other possibly related code, I found this in config/environments/development.rb -- possible problem?:

  # Debug mode disables concatenation and preprocessing of assets.
  # This option may cause significant delays in view rendering with a large
  # number of complex assets.
  config.assets.debug = true

EDIT -- adding a full stack trace from one of the errors I hit while running the feature specs:

# /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:125:in `[]'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:125:in `process_comment'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:88:in `s'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:82:in `block in stylesheet'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:545:in `block_contents'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:82:in `stylesheet'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:27:in `parse'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/engine.rb:342:in `_to_tree'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/engine.rb:315:in `_render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/engine.rb:262:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/sass_compressor.rb:24:in `evaluate'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/tilt-1.4.1/lib/tilt/template.rb:103:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/context.rb:197:in `block in evaluate'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/context.rb:194:in `each'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/context.rb:194:in `evaluate'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/bundled_asset.rb:25:in `initialize'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:377:in `new'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:377:in `build_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/index.rb:94:in `block in build_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/caching.rb:58:in `cache_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/index.rb:93:in `build_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:287:in `find_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/index.rb:61:in `find_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:295:in `[]'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:123:in `asset_digest_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:76:in `compute_asset_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_url_helper.rb:132:in `asset_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:91:in `asset_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_url_helper.rb:256:in `stylesheet_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_tag_helper.rb:100:in `block in stylesheet_link_tag'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_tag_helper.rb:96:in `map'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_tag_helper.rb:96:in `stylesheet_link_tag'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:170:in `stylesheet_link_tag'
 # ./app/views/layouts/application.html.haml:9:in `_app_views_layouts_application_html_haml__3935206380113339538_2226830520'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/template.rb:145:in `block in render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications.rb:161:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/template.rb:339:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/template.rb:143:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-mini-profiler-0.9.2/lib/mini_profiler/profiling_methods.rb:79:in `block in profile_method'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/template_renderer.rb:67:in `render_with_layout'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/template_renderer.rb:53:in `render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/template_renderer.rb:17:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/renderer.rb:42:in `render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/renderer.rb:23:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/rendering.rb:99:in `_render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/streaming.rb:217:in `_render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/rendering.rb:82:in `render_to_body'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rendering.rb:32:in `render_to_body'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/renderers.rb:32:in `render_to_body'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/rendering.rb:25:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rendering.rb:16:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:41:in `block (2 levels) in render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/core_ext/benchmark.rb:12:in `block in ms'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/core_ext/benchmark.rb:12:in `ms'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:41:in `block in render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:84:in `cleanup_view_runtime'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/railties/controller_runtime.rb:25:in `cleanup_view_runtime'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:40:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/implicit_render.rb:10:in `default_render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:238:in `default_render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:165:in `to_html'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:158:in `respond'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:151:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/mime_responds.rb:400:in `respond_with'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/devise-3.4.1/app/controllers/devise/sessions_controller.rb:11:in `new'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/base.rb:189:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rendering.rb:10:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:113:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:113:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:229:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:229:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:86:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:86:in `run_callbacks'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/callbacks.rb:19:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rescue.rb:29:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications.rb:159:in `block in instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications.rb:159:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/base.rb:136:in `process'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/rendering.rb:30:in `process'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-mini-profiler-0.9.2/lib/mini_profiler/profiling_methods.rb:79:in `block in profile_method'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal.rb:196:in `dispatch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal.rb:232:in `block in action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:82:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:82:in `dispatch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:50:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/mapper.rb:45:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/journey/router.rb:71:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/journey/router.rb:59:in `each'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/journey/router.rb:59:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:678:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/warden-1.2.3/lib/warden/manager.rb:35:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/warden-1.2.3/lib/warden/manager.rb:34:in `catch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/warden-1.2.3/lib/warden/manager.rb:34:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/etag.rb:23:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/conditionalget.rb:25:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/head.rb:11:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/flash.rb:254:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/cookies.rb:560:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/query_cache.rb:36:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:621:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:82:in `run_callbacks'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/airbrake-4.1.0/lib/airbrake/rails/middleware.rb:13:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/rack/logger.rb:38:in `call_app'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/rack/logger.rb:20:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/tagged_logging.rb:68:in `block in tagged'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/tagged_logging.rb:26:in `tagged'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/tagged_logging.rb:68:in `tagged'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/rack/logger.rb:20:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/request_store-1.1.0/lib/request_store/middleware.rb:8:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/request_id.rb:21:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/runtime.rb:17:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/cache/strategy/local_cache_middleware.rb:26:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/static.rb:64:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/sendfile.rb:112:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/airbrake-4.1.0/lib/airbrake/user_informer.rb:16:in `_call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/airbrake-4.1.0/lib/airbrake/user_informer.rb:12:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-timeout-0.1.1/lib/rack/timeout.rb:104:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-mini-profiler-0.9.2/lib/mini_profiler/profiler.rb:193:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/engine.rb:514:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/application.rb:144:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/builder.rb:138:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/urlmap.rb:65:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `each'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-test-0.6.3/lib/rack/mock_session.rb:30:in `request'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-test-0.6.3/lib/rack/test.rb:244:in `process_request'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-test-0.6.3/lib/rack/test.rb:58:in `get'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:60:in `process'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:38:in `block in process_and_follow_redirects'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:37:in `times'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:37:in `process_and_follow_redirects'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:21:in `visit'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/driver.rb:42:in `visit'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/session.rb:227:in `visit'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/dsl.rb:51:in `block (2 levels) in <module:DSL>'
 # ./spec/features/authentication_spec.rb:7:in `block (3 levels) in <top (required)>'
 # ./spec/support/background_jobs.rb:14:in `block (3 levels) in <top (required)>'
 # ./spec/support/background_jobs.rb:5:in `run_background_jobs_immediately'
 # ./spec/support/background_jobs.rb:13:in `block (2 levels) in <top (required)>'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus/rails.rb:208:in `test'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:148:in `block in command'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:135:in `fork'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:135:in `command'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:50:in `go'

Updates

Following coreyward's advice, I set the Rack timeout to 25 seconds and set up some profiling tools. The increase in the timeout (which was dev-environment specific) made the problem go away on localhost. But, perplexingly, I didn't seem to experience any load times of 5+ seconds at all, according to NewRelic and MiniProfiler. I think the longest load time I got was around 3 seconds, and I only got that once. I improved a query, and didn't bump into load times that high again. So it's weird that I bumped into that 5-second limit.

Basically, the load time problem seemed to disappear when I increased the Rack timeout. But I there's still something weird going on, cause the feature tests will still time out in Continuous Integration tests and occasionally on local .

I since cleaned up my asset situation (got rid of Bower and NPM, and did everything through the Gemfile, usually using the Rails-Assets gem). I also upgraded to Rails 4.2 and Ruby 2.2 for performance enhancements. Things generally appear to load a bit faster, according to profiling.

But I'm still getting the same test failures. Interestingly, on my Continuous Integration tool, the tests pretty much always fail, and when they do, they fail with a different error (I captured with a screenshot).

Internal Server Error

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

________________________________

WEBrick/1.3.1 (Ruby/2.2.0/2014-12-25) at 127.0.0.1:47539

This suggests it's a DB issue. My DB set up (database.yml) for the Test environment (which my CI uses) is below:

  adapter: postgresql
  database: planit_development
  encoding: utf8
  host: localhost
  min_messages: warning
  pool: 2
  timeout: 5000

But, weirdly, my local test suite, which has the same settings, tends to pass (unless I mess with an asset file, in which case there's a chance a feature spec will fail on the first, but not subsequent, run(s)). And the tests that are failing are the least database-intensive tests in the whole suite (just basic auth flow testing).

The profiling definitely helped me fix some mistakes, but I'm still pretty stumped here about what's the root cause of what appears to be a continuing problem. Any ideas based on this new info? Or any sense of what else I should look into?

Answer 1

There are a number of ways to debug this. To start, increase the Rack::Timeout time to 25 seconds — while this might seem like it's going to make matters worse, it will allow you to accurately assess the actual time the request is taking (5.1s is a different story than 25s).

Instrument a monitoring tool like NewRelic or Skylight. The former is more popular and can be easily configured to log traces on all requests over a certain threshold. This will allow you to see (roughly) where the time is being spent, as well as parameters/request information that relates to it.

If you think that the requests that are failing are to assets, I would double check that you have asset compilation turned off in production. You want this in production.rb:

# Do not fallback to assets pipeline if a precompiled asset is missed.
config.assets.compile = false

This means that you need to make every asset you're serving precompile. You can test that your setup is correct by running rake assets:precompile and verifying that the output in public/assets is what you're anticipating.

Make sure you're also outputting logs somewhere you can access them later — I prefer Papertrail, but there are undoubtedly others. This will allow you to find errors when they occur, especially 404s (which is what you'll see if you have requests for assets that are not precompiled). Once you isolate and resolve the issue you can lower this, but I still wouldn't set it lower than 15s.

Garbage collection is another potential culprit for intermittently long request times, though 5 seconds is probably excessive. Newer versions of Ruby (notably, 2.2) are better about managing this, so if you can bump the version you're using that might improve things.

Good luck!