ActionController::Live chokes at @buf.push?

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.

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'

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

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?

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