Version 2.2.x breaks Rails Actioncontroller:Live streaming

[alor]

When you upgrade rack from 2.1.x to 2.2.x the streaming functionality in rails stops working.
A simple controller like this:

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

  def index

    response.headers["X-Accel-Buffering"] = "no"
    response.headers['Content-Type'] = 'text/event-stream'

    5.times do |i|
      logger.info "stream"

      response.stream.write "hello #{i}\n"
      sleep 1
    end
  rescue ActionController::Live::ClientDisconnected => e
    # ignore client disconnections
    nil
  ensure
    response.stream.close
  end
  
end

will not stream anymore and will send all the data at the end of the cicle.
After many attempts I've pinned down that the culprit is Rack 2.2.x.

with version 2.2.0 if you invoke that controller will raise an exception:

#<NoMethodError: undefined method `reject' for nil:NilClass>
ruby-2.6.5@mod/gems/rack-2.2.0/lib/rack/request.rb:623:in `reject_trusted_ip_addresses'
ruby-2.6.5@mod/gems/rack-2.2.0/lib/rack/request.rb:363:in `ip'
ruby-2.6.5@mod/gems/actionpack-5.1.2/lib/action_dispatch/http/request.rb:250:in `ip'
ruby-2.6.5@mod/gems/railties-5.1.2/lib/rails/rack/logger.rb:51:in `started_request_message'
ruby-2.6.5@mod/gems/railties-5.1.2/lib/rails/rack/logger.rb:35:in `block in call_app'
ruby-2.6.5/lib/ruby/2.6.0/logger.rb:465:in `add'

with version 2.2.1 no exception is raised but the streaming does not work. same on version 2.2.2

I've tested it with Rails 5.1.x and 6.0.2.1 (the latest). Same behaviour.

[jeremyevans]

Sorry for the delay in responding. I think Rails was premature to close this issue. We have not confirmed it is a bug in Rack (it may be, but we don't know yet). It could be due to Rails relying on Rack implementation details that changed between Rack 2.1 and Rack 2.2.

Can you please do at least one of the following (preferably both):

1. Use git bisect to determine which commit in Rack made it start failing?

2. Remove the Rails specific parts of your example code and provide a self-contained reproducer that fails on Rack 2.2 and succeeds on Rack 2.1.

[ioquatix]

I am happy to investigate this too, but ideally need an isolated example as outlined above. Otherwise, can you make a rails app (in a github repo) which fails, with instructions on what to do to make it fail.

[rafaelfranca]

This is likely the commit that broke it. 290523f

Looking the reported backtrace it is very clear that this is broken in rack not Rails. It is failing when calling Rack::Request#ip and Rails has no part to play in that method.

Rack::Request#forwarded_for is returning nil and that is what is failing

rack/lib/rack/request.rb

Line 361 in 39d501a

forwarded_ips = self.forwarded_for

.

Before that commit the code correspondent to forwarded_for always returned an Array.

290523f#diff-345b5336fcb3ce47a50decd2176d79e8L291-L292.

[rafaelfranca]

A fix would change forwarded_for to return an array or change reject_trusted_ip_addresses to deal with nil.

[ioquatix]

Yeah, it's my fault, I'll fix it. Sorry everyone!

[ioquatix]

The issue @rafaelfranca mentions is fixed already in v2.2.2

So there is some other reason why live streaming is not working.

Not sure what it is yet, investigating.

[ioquatix]

It looks like Rack::ETag is buffering the live response.

[ioquatix]

This config/application.rb avoids the issue:

module Streamy
  class Application < Rails::Application
    # Initialize configuration defaults for originally generated Rails version.
    config.load_defaults 5.2

    # Settings in config/environments/* take precedence over those specified here.
    # Application configuration can go into files in config/initializers
    # -- all .rb files in that directory are automatically loaded after loading
    # the framework and any gems in your application.

    config.middleware.delete Rack::ETag
  end
end

[ioquatix]

koyoko% curl -i --no-buffer http://localhost:3000/streaming
HTTP/1.1 200 OK
Content-Type: text/event-stream
Cache-Control: no-cache
X-Request-Id: 2747eb62-e12a-4a64-a48d-7ba51df3b383
X-Runtime: 0.002133
Transfer-Encoding: chunked

hello world
hello world
hello world
hello world
hello world

0371c69

What should we do? Revert?

[ioquatix]

Here is the discussion: #1416

I've often thought cache-control needed a few extra flags:

• static - content which is quickly generated and/or easily reproduced without much effort.
• dynamic - content which has been generated dynamically and therefore is a good candidate for caching.
• streaming - content which is dynamically generated in an incremental fashion. Can be cached provided it isn't specified no-cache and cache operation doesn't impact streaming behaviour.

[ioquatix]

Rather than using cache-control, it looks like pragma would be an acceptable header as defined by the RFC

[ioquatix]

Actually it looks like we can add custom tokens to cache-control: https://tools.ietf.org/html/rfc7234#section-5.2.3

[jefflasslett]

I'm out of my depth here, but humour me.
Yesterday I reported this issue to rails: rails/rails#38842
Basically, my SSE would not work and I tracked it down to Rack::ETag.

The calculation of the digest in Rack::ETag replaced the original body of the response.
I observed that, in my SSE response, the body was a Thread::SizedQueue. This is something that threads synchronise on. Rack::ETag replaced it with an Array.

I think this is at the core of the issue, but I acknowledge that I am not "in my lane". FWIW.

[jeremyevans]

Thread::SizedQueue#each is not defined, so a rack response where the body is a Thread::SizedQueue instance violates the rack spec, and any behavior in that case is undefined. I doubt that is actually the case, there may be other Rails magic going on to make it look like the body is Thread::SizedQueue when it is actually something else (or the each method is coming from elsewhere).

In any case, the issue is that Rack::ETag was previously not generating the ETag if Cache-Control was set to no-cache, and Rails sets that for the SSE responses. We started generating the ETag as a result of #1416. We could revert the #1416 change and it would fix the issue, but then we are left with the previous behavior where the ETag is not generated for all no-cache responses. Alternatively, Rails SSE support could set an ETag header on SSE responses. Rack::ETag does not generate the ETag if there is already an ETag header, so that would also fix the issue.

[jefflasslett]

Thread::SizedQueue#each is not defined, so a rack response where the body is a Thread::SizedQueue instance violates the rack spec,

Yep. The body has to respond to each

I doubt that is actually the case, there may be other Rails magic going on to make it look like the body is Thread::SizedQueue

I could have become confused. The data in the response is complex. But I did pry through it. Also, I couldn't invent it. Before yesterday, I hadn't even heard of Thread::SizedQueue. :-)
Also, making the body only appear to be a Thread::SizedQueue seems a bit of a contortion.
So confusion on my part is a possibility, but it might be worth checking out.

Rack::ETag does not generate the ETag if there is already an ETag header, so that would also fix the issue.

That's what I went with.

[ioquatix]

@jefflasslett excellent work debugging the issue and finding a solution.

I think a better solution is needed. Maybe this is another point in favour of body#call style approach.

I think I will implement support for cache-control: streaming in falcon because I do need it to improve cache handling. However, I think there are multiple equally good solutions here, so happy to continue the discussion.

[jefflasslett]

Thanks @ioquatix . FWIW, I was content to bypass Rack::ETag for my text/event-stream response as the whole idea of the ETag header and digest does not seem relevent to the event stream.

[ioquatix]

That makes sense. Can you show the code you used to bypass ETag in case someone else wants to use the same approach?

Then, maybe a 3rd option is to sniff the content-type and don't generate ETag for that particular one... but that also seems a bit unreliable to me.

[jefflasslett]

Here's a piece of the relevant controller. You can set either or both of ETag or Last-Modified and that will cause Rack::Etag to let the response through without modifying the body, due to the !skip_cache?(headers) condition inside Rack::ETag#call.

Anyway, the controller fragment ...

  class CreditDecisionsController < ApplicationController
    include ActionController::Live

    def subscribe
      connect_to_redis
      app_number = find_application_number
      @redis_channel = "#{current_user.login}:#{app_number}"
      
      headers['Content-Type'] = 'text/event-stream'

      # These seem to be needed here, or the etag middleware
      # will add the 'etag' header and replace the body of the response, which will
      # kill the response. This is due to the way the etag middleware calculates
      # the digest value for the header.
      headers['Last-Modified'] = '0'
      headers['ETag'] = '0'

      @sse = SSE.new(response.stream, event: 'credit_decision')

      # The rest deleted.  You get the picture.

Probably should set ETag and/or Last-Modified properly, but that works.

[ioquatix]

Thanks for the update!

To me:

      headers['Last-Modified'] = '0'
      headers['ETag'] = '0'

Looks like a hack. It's okay, but not great.

Because 0 is probably a valid etag.

[jefflasslett]

:-)
That's fair. I did say that they should be set "properly". Just having either one present in the response will cause Rack::ETag to let the response through unchanged.

[ioquatix]

We have decided not to backport this, so the fix in Rack 2.x is either:

• Don't use Rack::ETag as it will buffer your response.
• Wait for Rack 3.x (by the end of the year I hope), because it's fixed.
• Use the hack suggested above: response.headers['Last-Modified'] = Time.now.httpdate.

[wynksaiddestroy]

Can someone verify that this issue was fixed in Rack 3.x? I tried to spy a relevant entry in the changelog, but couldn't find any. Thanks in advance!

[ioquatix]

It should be.

[gobijan]

Not fixed for me using Rails 7.0.4 + Ruby 3.2.0. Had to disable etag middleware.

[jeremyevans]

Not fixed for me using Rails 7.0.4 + Ruby 3.2.0. Had to disable etag middleware.

Considering that Rails 7.0.4 requires Rack 2, that's expected. You'll need to wait until Rails supports Rack 3.

[gobijan]

My bad. Sorry!

[vassebas]

For me it wasn't rack version was puma version. I was using rails 5.2.4, rack 2.2.4 and puma 6.0.0. There is an issue in Puma repo about this. My temporal solution was downgrade Puma to 5.6.5 version.

[jarthod]

For me it wasn't rack version was puma version. I was using rails 5.2.4, rack 2.2.4 and puma 6.0.0. There is an issue in Puma repo about this. My temporal solution was downgrade Puma to 5.6.5 version.

About this problem which I also ran into, for the record the fix has already been released in puma 6.0.1 I believe, or at least in 6.0.2 that I'm using it's working fine.

[dentarg]

Yes, the streaming issue (puma/puma#3000) was addressed in Puma 6.0.1 along with other issues (puma/puma#2999).

[renny-ren]

I'm developing on a new Rails 7 project today and found the stream response is not work. I'm following this doc (https://api.rubyonrails.org/v7.0.4/classes/ActionController/Live/SSE.html) to learn SSE.

It took me hours to find out the issue is about rack... Fortunately I finally found the hack solution here, yes I checked my rack version is 2.2.6, the solution should be written on the doc I guess, can't believe I'm using a broken default installation of rails that is not able to stream responses.

[RogerPodacter]

To confirm for future people trying to get ActionController::Live working: currently it is not possible in Rails 7.0.4 to use ActionController::Live, correct?

[ioquatix]

I guess the answer is, streaming never really worked correctly with Rack 2.x unless very specific conditions were met, or you used the rack.hijack interface.

[jeremyevans]

That's a bit hyperbolic. Streaming worked fine in Rack 2 if you were not buffering the body (but Rack::ETag buffered the body by default). In Rack 2, you can either remove Rack::ETag from the middleware stack, or set the ETag or Last-Modified response headers to work around the issue.

[ioquatix]

Well, given that Rails includes Rack::ETag by default, I'm fairly sure my statement is accurate, considering the use case ActionController::Live which out of the box on Rails does not work and is widely reported as not working without the extra steps you mention.

[RogerPodacter]

Oh wow! I added config.middleware.delete Rack::ETag to my application.rb and now it works! It should definitely work out of the box, but I'm also shocked the fix is this simple (and yet basically impossible to find). This should go in the docs!

[megatux]

Oh wow! I added config.middleware.delete Rack::ETag to my application.rb and now it works! It should definitely work out of the box, but I'm also shocked the fix is this simple (and yet basically impossible to find). This should go in the docs!

totally removing the Etag middleware could bring some performance implications. You should do that only for specific controllers/paths

[jeremyevans]

Well, given that Rails includes Rack::ETag by default, I'm fairly sure my statement is accurate, considering the use case ActionController::Live which out of the box on Rails does not work and is widely reported as not working without the extra steps you mention.

It depends on how your statement is interpreted. I interpreted streaming in your statement to mean streaming with Rack, whereas it appears you intended it to mean streaming with Rails.

[triskweline]

totally removing the Etag middleware could bring some performance implications. You should do that only for specific controllers/paths

Note that with a standard Rails layout the ETag middleware produces random ETags that can never produce a cache hit. This is due to Rails including randomly masked CSRF tokens and CSP nonces in the <head> or individual forms. You may still see some performance benefits when you render partials without a full layout and without forms, or when rendering JSON.

I agree that including Rack::ETag in the default middleware stack should be reconsidered, but that's a discussion for Rails.

Further reading:

• Rails issue: ETag changes for every same request/response
• Rack::SteadyETag gem

[renny-ren]

the issue can be time-consuming for Rails users to diagnose but the workaround is simple, I'm not sure I should write here but for future people trying to get ActionController::Live working, I added the workaround in the docs (see PR above).

Note that Rails includes Rack::ETag by default, which will buffer your response. As a result, streaming responses may not work properly with Rack 2.2.x, and you may need to implement workarounds in your application.
You can either set the ETag or Last-Modified response headers or remove Rack::ETag from the middleware stack to address this issue.

Here's an example of how you can set the Last-Modified header if your Rack version is 2.2.x:

def stream
  response.headers["Content-Type"] = "text/event-stream"
  response.headers["Last-Modified"] = Time.now.httpdate # Add this line if your Rack version is 2.2.x
  ...
end

[ioquatix]

This should all be fixed in Rails 7.1 with Rack 3.