lzap
November 13, 2020, 10:09am
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 (https://github.com/theforeman/foreman ) 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.
lzap
November 13, 2020, 12:32pm
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'
lzap
November 13, 2020, 12:48pm
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
lzap
November 13, 2020, 1:30pm
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?
bensheldon
November 15, 2020, 3:11pm
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