Rails: Troubleshooting a Rack::Timeout::RequestTimeoutException

Question

Getting some:

Rack::Timeout::RequestTimeoutException: Request waited {7ms}, then ran for longer than 15000ms

After upgrading Rails 4.2.9 app to Rails 5.2.1.1.

This is raised by the rack-timeout gem documented here.

That said, I'm having trouble identifying the root cause of the timeouts. I can successfully load the URLs that were the triggers from my machine but clearly others users are having issues.

Any help in how to troubleshoot this would be appreciated.

Backtrace (from Airbrake – includes "code hunks"):

/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603 in async_exec
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603 in block (2 levels) in exec_no_cache
/gems/activesupport-5.2.1.1/lib/active_support/dependencies/interlock.rb:48 in block in permit_concurrent_loads
/gems/activesupport-5.2.1.1/lib/active_support/concurrency/share_lock.rb:187 in yield_shares
/gems/activesupport-5.2.1.1/lib/active_support/dependencies/interlock.rb:47 in permit_concurrent_loads
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:602 in block in exec_no_cache
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:579 in block (2 levels) in log
vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:214 in mon_synchronize
212:
    mon_enter
213:
    begin
214:
      yield
215:
    ensure
216:
      mon_exit
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:578 in block in log
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:569 in log
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:601 in exec_no_cache
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:590 in execute_and_clear
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:81 in exec_query
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:465 in select
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:57 in select_all
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:99 in block in select_all
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:122 in block in cache_sql
vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:214 in mon_synchronize
212:
    mon_enter
213:
    begin
214:
      yield
215:
    ensure
216:
      mon_exit
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:108 in cache_sql
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:99 in select_all
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:81 in select_rows
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:69 in select_value
/gems/activerecord-5.2.1.1/lib/active_record/relation/finder_methods.rb:322 in block in exists?
/gems/activerecord-5.2.1.1/lib/active_record/relation.rb:578 in skip_query_cache_if_necessary
/gems/activerecord-5.2.1.1/lib/active_record/relation/finder_methods.rb:322 in exists?
/gems/unread-0.10.1/lib/unread/readable.rb:124 in unread?
app/views/stories/_story.html.slim:4 in _app_views_stories__story_html_slim___4341629232572424476_47283389142580
2:
  - if story.time_capsule?
3:
    .flag = t("stories.time_capsule.label")
4:
  - elsif story.unread?(current_user)
5:
    .flag = t("stories.unread")
6:
  = link_to story_path(story), class: "open-block" do
/gems/actionview-5.2.1.1/lib/action_view/template.rb:159 in block in render
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/template.rb:354 in instrument_render_template
/gems/actionview-5.2.1.1/lib/action_view/template.rb:157 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/partial_renderer.rb:344 in block in render_partial
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:44 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:43 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/partial_renderer.rb:333 in render_partial
/gems/actionview-5.2.1.1/lib/action_view/renderer/partial_renderer.rb:312 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/renderer.rb:49 in render_partial
/gems/actionview-5.2.1.1/lib/action_view/helpers/rendering_helper.rb:36 in render
app/views/stories/index.html.slim:19 in block in _app_views_stories_index_html_slim___2178368229094429886_47283376767280
17:
      ul.stories.blocks
18:
        - @stories.each do |story|
19:
          = render "stories/story", story: story
20:
      = render 'comments/compact_list'
21:
    - else
app/views/stories/index.html.slim:18 in each
16:
    - if @stories.to_a.any?
17:
      ul.stories.blocks
18:
        - @stories.each do |story|
19:
          = render "stories/story", story: story
20:
      = render 'comments/compact_list'
app/views/stories/index.html.slim:18 in _app_views_stories_index_html_slim___2178368229094429886_47283376767280
16:
    - if @stories.to_a.any?
17:
      ul.stories.blocks
18:
        - @stories.each do |story|
19:
          = render "stories/story", story: story
20:
      = render 'comments/compact_list'
/gems/actionview-5.2.1.1/lib/action_view/template.rb:159 in block in render
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/template.rb:354 in instrument_render_template
/gems/actionview-5.2.1.1/lib/action_view/template.rb:157 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:54 in block (2 levels) in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:44 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:43 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:53 in block in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:61 in render_with_layout
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:52 in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:16 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/renderer.rb:44 in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/renderer.rb:25 in render
/gems/actionview-5.2.1.1/lib/action_view/rendering.rb:103 in _render_template
/gems/actionpack-5.2.1.1/lib/action_controller/metal/streaming.rb:219 in _render_template
/gems/actionview-5.2.1.1/lib/action_view/rendering.rb:84 in render_to_body
/gems/actionpack-5.2.1.1/lib/action_controller/metal/rendering.rb:52 in render_to_body
/gems/actionpack-5.2.1.1/lib/action_controller/metal/renderers.rb:142 in render_to_body
/gems/actionpack-5.2.1.1/lib/abstract_controller/rendering.rb:25 in render
/gems/actionpack-5.2.1.1/lib/action_controller/metal/rendering.rb:36 in render
/gems/actionpack-5.2.1.1/lib/action_controller/metal/instrumentation.rb:46 in block (2 levels) in render
/gems/activesupport-5.2.1.1/lib/active_support/core_ext/benchmark.rb:14 in block in ms
vendor/ruby-2.4.4/lib/ruby/2.4.0/benchmark.rb:308 in realtime
306:
  def realtime # :yield:
307:
    r0 = Process.clock_gettime(Process::CLOCK_MONOTONIC)
308:
    yield
309:
    Process.clock_gettime(Process::CLOCK_MONOTONIC) - r0
310:
  end
/gems/activesupport-5.2.1.1/lib/active_support/core_ext/benchmark.rb:14 in ms
/gems/actionpack-5.2.1.1/lib/action_controller/metal/instrumentation.rb:46 in block in render

Answer 1

I solved this issue removing:

gem 'rack-timeout'

And then run

rails server

Answer 2

If it helps, I solved the issue by running in the terminal the following command:

export RACK_TIMEOUT_SERVICE_TIMEOUT=30

Answer 3

I am having a very similar issue. 30s in my case. I was told it is an hard limit for Heroku. but now seeing you have a 15s timeout, there is something else. Maybe they have increased it in the last 9 months? (unlikely) or maybe it depends on the plan. or maybe it has nothing to do with Heroku, and it is the rack-timeout gem doing it.

according to their README. you can update RACK_TIMEOUT_SERVICE_TIMEOUT environment variable to something bigger

or remove the gem if you don't need production errors to report you slow endpoints... sigh

And I did have that var already set to 30s

I bumped it to 60s, I will let you know in a few days time if that fixes it

https://github.com/sharpstone/rack-timeout#rails-apps

Update: That gem does kill the request ahead of time, but the heroku limit also exist. if you disable that gem you will see the H12 being returned by heroku in your logs or metrics screen.

See this article for more details on their hard limit

https://devcenter.heroku.com/articles/limits