rails: Rack::ETag middleware doesn't play nice with Live streaming when commit! is called before write

Rack 2 does not have a good interface for streaming responses. Rack 3 will solve this problem as it introduces an explicit model for streaming and Rack::ETag follows that model. Therefore, I’d suggest once Rack 3 PR is merged, we will be able to close this issue.

I was going to push this as an issue, but I think it relates here. TL;DR Set a value for the ‘Last-Modified’ header in order to get the etag middleware to stop killing your SSE.

Steps to reproduce

I have a controller like so …

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'

    # Putting these here prevent the ETag middleware modifying
    # the response
    # headers['Last-Modified'] = '0'
    # headers['ETag'] = '0'

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

    begin
        @redis.subscribe(@redis_channel) do |on|
          on.message do |_, message|
            @sse.write("XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX")
            @sse.write(message)
          end
        end
        Rails.logger.debug "   DBG: SSE::CreditDecisionsController#subscribe: LOOP END"
    rescue IOError => io_error
      Rails.logger.debug "DBG: SSE::CreditDecisionsController#subscribe: IOError: #{io_error.message}"
    rescue ClientDisconnected => client_disconnected
      Rails.logger.debug "DBG: SSE::CreditDecisionsController#subscribe: ClientDisconnected: #{client_disconnected.message}"
    rescue StandardError => e
      Rails.logger.debug "DBG: SSE::CreditDecisionsController#subscribe: StandardError: #{e.message}"
    ensure
      Rails.logger.debug "DBG: SSE::CreditDecisionsController#subscribe: ENSURE"
      @sse.close
      @redis.close
    end
  end
end

Expected behavior

A request to this controller should persist and server-sent event should be sent to the browser whenever Redis publishes them to the subscribed channel.

Actual behavior

Nothing is sent. No data ends up “on the wire”. I’ve checked with wireshark. Digging into this a bit, it seems that the ETag rack middleware is causing the response to “disappear”.

# from rack-2.2.2/lib/rack/etag.rb

    def call(env)
      status, headers, body = @app.call(env)

      if etag_status?(status) && etag_body?(body) && !skip_caching?(headers)

        # Without 'Last-Modified' or 'ETag' headers, we end up in here.

        original_body = body
        digest, new_body = digest_body(body)
        body = Rack::BodyProxy.new(new_body) do
          original_body.close if original_body.respond_to?(:close)
        end
        headers[ETAG_STRING] = %(W/"#{digest}") if digest
      end

      unless headers[CACHE_CONTROL]
        if digest
          headers[CACHE_CONTROL] = @cache_control if @cache_control
        else
          headers[CACHE_CONTROL] = @no_cache_control if @no_cache_control
        end
      end

      [status, headers, body]
    end

I suspect the problem lies with the body replacement taking place here. The original body is a Thread::SizedQueue, on which threads are waiting, presumably. But then this middleware replaces that body with a plain array. I think that is the problem.

I am trying to understand what is the current workaround for rails 6.0.3.4 with rack 2.2.3 and puma 4.3.6. I think I tried every single combination of headers or workarounds but nothing seem to be working for me. Can you explain maybe in more detail what works for you? In all cases my request gets stuck because SizedQueue hits the limit (10 elements). Apparently nothing is picking up in the other thread.

https://discuss.rubyonrails.org/t/actioncontroller-live-chokes-at-buf-push/76490

a note on the above comment by @jefflasslett in https://github.com/rails/rails/issues/14358#issuecomment-605719033 which also bit me.

The relevant part of rack setting these tags, near as I can tell, is: https://github.com/rack/rack/blob/v2.2.2/lib/rack/etag.rb#L29 https://github.com/rack/rack/blob/2.0.8/lib/rack/etag.rb#L57

A little extra context:

When we bumped rails to 6.0.2 from 6.0.1 it bumped rack from 2.0.8 to 2.2.2, and that seems to change how rack was handling setting ETags - we’d been setting Cache-Control: no-cache in headers, and in 2.0.8 that triggers the skip, but it doesn’t in 2.2.2. For reasons I’m not totally clear on this made the browser interpret it as a not-streaming request, and it would try to download the (significantly sized) file in one go rather than streaming. NBD and we’re out of the woods now, but hopefully this saves someone else some trouble someday.

Setting the ETag header to nil seems to resolve for us as well.

(s/o @rosenfeld for making this issue and thanks to @rafaelfranca for keeping it open)