ActionController::Live chokes at @buf.push?

rubyonrails-core
#1

Hello,

I am working on some CSV/HTML report streaming and I learned that the only way to stream data to client without storing the whole (huge) output in a buffer is ActionController::Live. Our app is fairly big codebase with ton of dependencies (GitHub - theforeman/foreman: an application that automates the lifecycle of servers) and it uses Puma for both development and production.

Now, I am testing the feature and some of my queries get stucks. When I display callstack for the stuck process, I do see this:

11:02:03 rails.1   | Thread TID-93780
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:120:in `push'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:120:in `write'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/live.rb:152:in `write'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/lib/foreman/renderer/scope/report.rb:106:in `report_row'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/safemode-1.3.6/lib/safemode/scope.rb:37:in `method_missing'
11:02:03 rails.1   | Host - Statuses:54:in `block in bind'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches/batch_enumerator.rb:40:in `block (2 levels) in each_record'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches/batch_enumerator.rb:40:in `each'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches/batch_enumerator.rb:40:in `block in each_record'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches.rb:238:in `block in in_batches'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches.rb:222:in `loop'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches.rb:222:in `in_batches'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches/batch_enumerator.rb:39:in `each'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/relation/batches/batch_enumerator.rb:39:in `each_record'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/safemode-1.3.6/lib/safemode/jail.rb:31:in `method_missing'
11:02:03 rails.1   | Host - Statuses:53:in `bind'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/safemode-1.3.6/lib/safemode.rb:51:in `eval'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/safemode-1.3.6/lib/safemode.rb:51:in `eval'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/lib/foreman/renderer/safe_mode_renderer.rb:7:in `render'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/lib/foreman/renderer/base_renderer.rb:18:in `render'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/lib/foreman/renderer.rb:46:in `render'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/app/models/template.rb:172:in `render'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/app/models/report_composer.rb:241:in `render'
11:02:03 rails.1   | /home/lzap/Projekty/foreman/app/controllers/api/v2/report_templates_controller.rb:138:in `generate'

The CSV content is being generated in a ERB template with safemode gem (users of our app can define their own reports using ERB). What puzzles me how is possible that Rails gets stuck at @buf.push call:

      def write(string)
        raise IOError, "closed stream" if closed?

        @str_body = nil
        @response.commit!
        @buf.push string
      end

I am reading all the ActionController code and it looks like @buf should be a ruby array. That cannot block. Or is it set to a different variable?

Edit: I just discovered it is #<Thread::SizedQueue:0x00005575a92a6498>, I do see it now. It is limited to 10, something is not picking those up.

#2

Weird, the moment I have more than 10 lines, it gets stuck. If I have less, it goes through. The call stack when things are poped from the array:

13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:129:in `each'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:76:in `each'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:492:in `each'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/body_proxy.rb:41:in `method_missing'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/etag.rb:67:in `digest_body'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/etag.rb:31:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/cookies.rb:648:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activerecord-6.0.3.4/lib/active_record/migration.rb:567:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:101:in `run_callbacks'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/rack/logger.rb:37:in `call_app'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/rack/logger.rb:28:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/sprockets-rails-3.2.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/host_authorization.rb:82:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/secure_headers-6.3.1/lib/secure_headers/middleware.rb:11:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/engine.rb:527:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/railtie.rb:190:in `public_send'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/railtie.rb:190:in `method_missing'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/configuration.rb:228:in `call'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/server.rb:713:in `handle_request'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/server.rb:472:in `process_client'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/server.rb:328:in `block in run'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/thread_pool.rb:134:in `block in spawn_thread'
13:28:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
#3

One more info, puma starts in 0:16 mode, not sure if that’s relevant.

13:37:34 rails.1   | Puma starting in single mode...
13:37:34 rails.1   | * Version 4.3.6 (ruby 2.7.2-p137), codename: Mysterious Traveller
13:37:34 rails.1   | * Min threads: 0, max threads: 16
13:37:34 rails.1   | * Environment: development
13:37:34 rails.1   | * Listening on tcp://127.0.0.1:5000
13:37:34 rails.1   | * Listening on tcp://[::1]:5000
13:37:34 rails.1   | Use Ctrl-C to stop
#4

I think I am running into this issue: Rack::ETag middleware doesn't play nice with Live streaming when commit! is called before write · Issue #14358 · rails/rails · GitHub

When I set response.headers['ETag'] = '0' then the stacktrace looks cleaner:

14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:129:in `each'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:76:in `each'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/response.rb:492:in `each'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/body_proxy.rb:41:in `method_missing'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/body_proxy.rb:41:in `method_missing'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/body_proxy.rb:41:in `method_missing'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/body_proxy.rb:41:in `method_missing'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/rack-2.2.3/lib/rack/body_proxy.rb:41:in `method_missing'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/server.rb:848:in `handle_request'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/server.rb:472:in `process_client'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/server.rb:328:in `block in run'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/puma-4.3.6/lib/puma/thread_pool.rb:134:in `block in spawn_thread'
14:15:38 rails.1   | /home/lzap/Projekty/foreman/vendor/ruby/ruby/2.7.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

Still it does not work. It looks like Rails does not start the background thread that is supposed to process the events? Or what is wrong?

#5

Let me first apologize that I don’t have experience with ActionController::Live, but I do have experience with streaming CSVs using an Enumerator instead. I wonder if it would work for you alternatively:

This is my controller action, in which I’m streaming the CSV directly from Postgres:

 # https://medium.com/table-xi/stream-csv-files-in-rails-because-you-can-46c212159ab7
  def stream_csv_report(query)
    headers.delete("Content-Length")
    headers["Cache-Control"] = "no-cache"
    headers["X-Accel-Buffering"] = "no"

    headers["Content-Type"] = "text/csv"
    headers["Content-Disposition"] = "attachment; filename=\"#{csv_filename}\""
    headers["Last-Modified"] = Time.current.ctime.to_s

    self.response_body = Enumerator.new do |response_output|
      MyModel.stream_rows(query.to_sql, "WITH CSV HEADER") do |row_from_db|
        response_output << row_from_db
      end
    end

    response.status = 200
  end
More Resources

Keep up to date with Rails on Twitter and This Week in Rails

Policies: Conduct, License, Maintenance, Security, Trademarks