rails: ActionController::Live hangs with Deadlock after upgrading to rails 5.1.4

In a project i recently upgraded from rails 4.2.8 to 5.1.4. There is a CSV export using ActionController::Live to stream line for line.

class UsersController < ApplicationController
  include ActionController::Live
  respond_to :csv

  #before_action :authenticate_administrator

  def index
    response_header
    response_data
  ensure
    response.stream.close
  end

  private

  def response_header
    response.headers['Content-Disposition'] = 'attachment; filename=users.csv'
    response.headers['Content-Type'] = 'text/csv'

    # Write csv header once ...
    response.stream.write CSV.generate_line(user_fields + personal_detail_fields + additional_fields)
  end

  def response_data
    # .. and generate a line for each user.
    User.each do |user|
      next if user.personal_detail.blank?
      response.stream.write CSV.generate_line(user_values(user) + personal_detail_values(user) + additional_values(user))
    end
  end
....

Expected behavior

Normally the code streams the CSV by sending the CSV line by line.

Actual behavior

After several lines the stream hangs in an unknown state. The production server is blocked and I have to restart the webserver.

To investigate the problem, I changed the code using this example from the API reference.

class MyController < ActionController::Base
  include ActionController::Live

  def stream
    response.headers['Content-Type'] = 'text/event-stream'
    100.times { |i|
      response.stream.write "hello world\n"
      puts i
      sleep 1
    }
  ensure
    response.stream.close
  end
end

I figured out that it breaks as soon as I invoke response.stream.write after about 10 writes. Without writing to the stream it do not break.

Exiting the webserver it shows a Deadlock.

$ rails s
=> Booting WEBrick
=> Rails 5.1.4 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
Error connecting to Redis on 127.0.0.1:6379 (Errno::ECONNREFUSED)
^[[A[2017-11-22 16:04:53] INFO  WEBrick 1.3.1
[2017-11-22 16:04:53] INFO  ruby 2.3.1 (2016-04-26) [x86_64-darwin16]
[2017-11-22 16:04:53] INFO  WEBrick::HTTPServer#start: pid=6561 port=3000
Started GET "/users.csv" for ::1 at 2017-11-22 16:05:01 +0100
Processing by UsersController#index as CSV
[ahoy] Visit excluded
0
1
2
3
4
5
6
7
8
9
^C[2017-11-22 16:05:51] INFO  going to shutdown ...
Exiting
Completed 401 Unauthorized in 49927ms


::1 - - [22/Nov/2017:16:05:01 CET] "GET /users.csv HTTP/1.1" 200 0
- -> /users.csv
/Users/markus/.rbenv/versions/2.3.1/lib/ruby/2.3.0/webrick/server.rb:215:in `join': No live threads left. Deadlock? (fatal)
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/2.3.0/webrick/server.rb:215:in `block (2 levels) in start'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/2.3.0/webrick/server.rb:215:in `each'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/2.3.0/webrick/server.rb:215:in `block in start'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/2.3.0/webrick/server.rb:33:in `start'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/2.3.0/webrick/server.rb:164:in `start'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/rack-2.0.3/lib/rack/handler/webrick.rb:34:in `run'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/rack-2.0.3/lib/rack/server.rb:a297:in `start'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:44:in `start'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:135:in `block in perform'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:130:in `tap'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/commands/server/server_command.rb:130:in `perform'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/thor-0.20.0/lib/thor/command.rb:27:in `run'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/thor-0.20.0/lib/thor/invocation.rb:126:in `invoke_command'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/thor-0.20.0/lib/thor.rb:387:in `dispatch'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/command/base.rb:63:in `perform'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/command.rb:44:in `invoke'
	from /Users/markus/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/railties-5.1.4/lib/rails/commands.rb:16:in `<top (required)>'
	from bin/rails:8:in `require'
	from bin/rails:8:in `<main>'

Any Ideas, how to solve this issue? I also setup a new empty rails project and added the streaming as described below. Then it works without any issue, so I guess some interference with a gem?

System configuration

Rails version: Rails 5.1.4

Ruby version: ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-darwin16]

bundle show:

Gems included by the bundle:
  * actioncable (5.1.4)
  * actionmailer (5.1.4)
  * actionpack (5.1.4)
  * actionview (5.1.4)
  * activejob (5.1.4)
  * activemodel (5.1.4)
  * activerecord (5.1.4)
  * activesupport (5.1.4)
  * addressable (2.5.2)
  * ahoy_matey (1.6.0)
  * airbrussh (1.3.0)
  * arel (8.0.0)
  * autoprefixer-rails (7.1.6)
  * aws-partitions (1.34.0)
  * aws-sdk-core (3.7.0)
  * aws-sdk-ec2 (1.17.0)
  * aws-sigv4 (1.0.2)
  * bcrypt (3.1.11)
  * better_errors (2.4.0)
  * bindex (0.5.0)
  * binding_of_caller (0.7.3)
  * bootstrap-sass (3.3.7)
  * breadcrumbs_on_rails (3.0.1)
  * browser (2.5.2)
  * bson (4.2.2)
  * builder (3.2.3)
  * bundler (1.16.0)
  * byebug (9.1.0)
  * capistrano (3.10.0)
  * capistrano-bundler (1.1.4)
  * capistrano-passenger (0.2.0 6dc408e)
  * capistrano-rails (1.3.0)
  * capistrano-sidekiq (0.20.0 973c368)
  * capybara (2.15.4)
  * carmen (1.0.2)
  * carmen-rails (1.0.1)
  * chartkick (2.2.5)
  * childprocess (0.8.0)
  * cliver (0.3.2)
  * codemirror-rails (5.16.0)
  * coderay (1.1.2)
  * coffee-rails (4.2.2)
  * coffee-script (2.4.1)
  * coffee-script-source (1.12.2)
  * concurrent-ruby (1.0.5)
  * connection_pool (2.2.1)
  * crass (1.0.2)
  * css_parser (1.6.0)
  * debug_inspector (0.0.3)
  * devise (4.3.0)
  * diff-lcs (1.3)
  * docile (1.1.5)
  * dotenv (2.2.1)
  * dotenv-rails (2.2.1)
  * errbase (0.0.3)
  * erubi (1.7.0)
  * erubis (2.7.0)
  * et-orbi (1.0.8)
  * exception_notification (4.2.2)
  * execjs (2.7.0)
  * factory_bot (4.8.2)
  * faker (1.8.4)
  * faraday (0.12.2)
  * ffi (1.9.18)
  * font-awesome-sass (4.7.0)
  * geocoder (1.4.4)
  * globalid (0.4.1)
  * google_timezone (0.0.5)
  * haml (5.0.4)
  * haml-rails (1.0.0)
  * hashie (3.5.6)
  * helena (1.3.0)
  * helena_administration (0.3.4)
  * html2haml (2.2.0)
  * html5-rails (0.1.0)
  * i18n (0.9.1)
  * i18n-js (3.0.2)
  * jmespath (1.3.1)
  * jquery-rails (4.3.1)
  * json (1.8.6)
  * jwt (1.5.6)
  * kaminari-actionview (1.1.1)
  * kaminari-core (1.1.1)
  * kaminari-mongoid (1.0.1)
  * kgio (2.11.0)
  * launchy (2.4.3)
  * libv8 (3.16.14.19)
  * loofah (2.1.1)
  * mail (2.7.0)
  * mail_form (1.7.0)
  * method_source (0.9.0)
  * mime-types (3.1)
  * mime-types-data (3.2016.0521)
  * mini_mime (1.0.0)
  * mini_portile2 (2.3.0)
  * minitest (5.10.3)
  * mongo (2.4.3)
  * mongoid (6.2.1)
  * mongoid-rspec (4.0.0.pre.alpha1 f392d24)
  * mongoid-sadstory (0.0.2)
  * mongoid-simple-tags (0.1.3)
  * mongoid-tree (2.1.0)
  * mongoid_orderable (4.1.1)
  * multi_json (1.12.2)
  * multi_xml (0.6.0)
  * multipart-post (2.0.0)
  * mustermann (1.0.1)
  * net-scp (1.2.1)
  * net-ssh (4.2.0)
  * nio4r (2.1.0)
  * nokogiri (1.8.1)
  * oauth (0.5.3)
  * oauth2 (1.4.0)
  * omniauth (1.7.1)
  * omniauth-facebook (4.0.0)
  * omniauth-oauth (1.1.0)
  * omniauth-oauth2 (1.4.0)
  * omniauth-twitter (1.4.0)
  * orm_adapter (0.5.0)
  * poltergeist (1.16.0)
  * pry (0.11.2)
  * pry-byebug (3.5.0)
  * public_suffix (3.0.1)
  * rack (2.0.3)
  * rack-accept (0.4.5)
  * rack-attack (5.0.1)
  * rack-protection (2.0.0)
  * rack-test (0.7.0)
  * rails (5.1.4)
  * rails-boilerplate (0.1.9)
  * rails-dom-testing (2.0.3)
  * rails-html-sanitizer (1.0.3)
  * rails-i18n (5.0.4)
  * railties (5.1.4)
  * raindrops (0.19.0)
  * rake (12.2.1)
  * rb-fsevent (0.10.2)
  * rb-inotify (0.9.10)
  * redis (4.0.1)
  * ref (2.0.0)
  * referer-parser (0.3.0)
  * request_store (1.3.2)
  * responders (2.4.0)
  * roadie (3.2.2)
  * roadie-rails (1.2.1)
  * route_translator (5.5.0)
  * rspec (3.7.0)
  * rspec-collection_matchers (1.1.3)
  * rspec-core (3.7.0)
  * rspec-expectations (3.7.0)
  * rspec-mocks (3.7.0)
  * rspec-rails (3.7.1)
  * rspec-support (3.7.0)
  * ruby_parser (3.10.1)
  * rubyzip (1.2.1)
  * rufus-scheduler (3.4.2)
  * safely_block (0.2.0)
  * sass (3.5.3)
  * sass-listen (4.0.0)
  * sass-rails (5.0.6)
  * selenium-webdriver (3.7.0)
  * sexp_processor (4.10.0)
  * sidekiq (5.0.5)
  * sidekiq-cron (0.6.3)
  * simple_form (3.5.0)
  * simplecov (0.15.1)
  * simplecov-html (0.10.2)
  * sinatra (2.0.0)
  * slack-notifier (2.3.1)
  * slim (3.0.9)
  * slim-rails (3.1.3)
  * sprockets (3.7.1)
  * sprockets-rails (3.2.1)
  * sshkit (1.15.0)
  * temple (0.8.0)
  * therubyracer (0.12.3)
  * thor (0.20.0)
  * thread_safe (0.3.6)
  * tilt (2.0.8)
  * turnout (2.4.1)
  * tzinfo (1.2.4)
  * uglifier (3.2.0)
  * unicorn (5.3.1)
  * user_agent_parser (2.4.1)
  * uuidtools (2.1.5)
  * warden (1.2.7)
  * web-console (3.5.1)
  * websocket-driver (0.6.5)
  * websocket-extensions (0.1.3)
  * wicked_pdf (1.1.0)
  * xpath (2.1.0)

About this issue

  • Original URL
  • State: closed
  • Created 7 years ago
  • Reactions: 6
  • Comments: 22 (2 by maintainers)

Commits related to this issue

Most upvoted comments

It’s quite an old and closed issue but I thought I mention my workaround for this problem when using RSpec (until some permanent solution is introduced). Someone may find it useful.

I created this little helper method:

def consume_streamed_response
  consumer_thread = nil
  allow(controller).to receive(:dispatch).and_wrap_original do |m, *args|
    consumer_thread = Thread.new { response.body }
    m.call(*args)
    consumer_thread.join
  end
  yield
  consumer_thread.value
end

It can be used as such:

it('consumes the streamed respose') do
  response_body = consume_streamed_response { get :streaming_endpoint }
  expect(response_body).to eq(...)
end

Normally the deadlock occurs because - as mentioned above - ActionController::Live is single-threaded in RSpec due to the redefinition of the new_controller_thread method in action_controller/test_case.rb: the SizedQueue fills up and it waits until the response gets consumed, but the response can’t be processed because in a single-threaded environment it happens after the controller has finished with the request.

The method above starts reading response.body in a new thread, and the main thread (in which the spec is running) waits for it to finish (consumer_thread.join). The new thread is created just before the request is dispatched to the controller to make sure that the response getter returns the same LiveTestResponse instance the controller.dispatch is called with (creating a new response instance and dispatching the request to the controller happens in ActionController::TestCase::Behavior#process).

It worked for my use case but I haven’t done any extensive testing so I can’t guarantee that it works for everyone ¯\_(ツ)_/¯.

+7
sandrasi on Feb 11, 2019

I just ran into this while testing a controller that has ActionController::Live. A minitest solution for those who find this, I stubbed SizedQueue.new to use a larger queue, i.e.:

require 'minitest/autorun'
...

SizedQueue.stub :new, SizedQueue.new(1000) do
  get :streaming_path
end
+1
npresco on Jun 14, 2020

this issue is still happening with rails 4.2.11!

+1
brauliobo on Mar 21, 2019

Raising an exception including some dirty swearwords in ActionController::TestCase::Behavior turned out that the gem route_translator suffers from a similar issue as gon. So I fixed it in the same way in https://github.com/enriclluelles/route_translator/pull/183. I agree that test related code in production code should be separated. Querying the environment is one way, but we could think about going a step further by including it in the test code only. This could be done by monkey patching when loading tests only.

@rcugut Thanks for pointing out this issue. I owe you a beer at least.

@tenderlove Even if it is not good practice to include test-related code as it happens here, I think killing new_controller_thread as you did in https://github.com/rails/rails/commit/a640da454fdb9cd8806a1b6bd98c2da93f1b53b9 is also not the best approach. As I am not so deep into rails development I have not a solution at the moment. It is more intuitive.

EDIT: I should also mention that this bug affects every testing controllers including ActionController::Live using rspec if you send more then 10 responses. An example is the following test: https://github.com/gurix/pana-nonverbal-validation/blob/4cae5ec5f06a9a0b916d79c1698a6b4424bead65/spec/features/export/show_spec.rb#L8. This because rspec also includes ActionController::TestCase::Behavior by default.

+1
gurix on Mar 22, 2018
Read more comments on GitHub
← rails: ActionCable's SubscriptionAdpater for Redis does not reconnect after a connection loss.
rails: ActionController::RoutingError (No route matches [GET] "/assets/application.js....)  →