David - Musings of an SRE

Creating my first Rack Middleware with Rack::ContentLength

Yeah, I’m probably pretty slow in the game but I think I’ve finally wrapped my head around all the countless Rack Middlewares out there.

The goal of this was to create a response_logger that intercepts the response object on the middleware level and send out a log with the size of the JSON object that it returns for future reference.

I first setup Rack::ContentLength, which is a great Middleware that’s available out of the box if you’re on Rails.

You just have to add it in your config/application.rb

  # config/application.rb
  config.middleware.use Rack::ContentLength

Now, when your Rails app sends a response, it adds a Content-Length key/value in the response header.

To me, this is not enough because the response will only be read by the clients and there is no way I can have information about it other than intercepting it and logging it myself.

So I learnt that this is one of the best use cases for Middlewares.

Did some reading, ended up with this:

# lib/response_logger.rb
class ResponseLogger
 include Rack::Utils
  def initialize(app, message = "Response Time")
    @app = app
    @message = message
  end
  
  def call(env)
    dup._call(env)
  end

  def _call(env)
    @status, @headers, @response = @app.call(env)
    Rails.logger.info "#{env["REQUEST_URI"]} - #{env["rack.request.query_hash"]}
- #{@headers['Content-Length'].to_i} bytes"

    [@status, @headers, self]
  end

  def each(&block)
#    block.call("<!-- #{@message}: #{@stop - @start} -->\n") if
@headers["Content-Type"].include? "text/html"
    @response.each(&block)
  end
end

Everything here is pretty standard other than returning of the Rails.logger.info. This is the meat.

I just have to require it in my config/application and I’m all set.

First, I want to make sure that I capture the @response and environment objects at the last stage of the Middleware cycle, so that I can capture the modified response header by Rack::ContentLength.

Take a look at the Rack Middleware order:

$ rake middleware

use Rack::Sendfile
use ActionDispatch::Static
use Rack::Lock
use #<ActiveSupport::Cache::Strategy::LocalCache::Middleware:0x0000000653ef48>
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::Migration::CheckPending
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use Warden::Manager
use Rack::ContentLength
use Bullet::Rack
run MyApp::Application.routes

If you read from the top down, ContentLength appears at the bottom of the list. This means it gets initialized quite late in the cycle. and because rack applications are made up of encapsulating @app.call responses, this means that the later it gets initialized, the earlier it gets returned. Think of it as a Russian Doll.

Russian Doll

When you first start, you start with one doll, then you put a bigger doll over it, and so on and so forth. Each doll encapsulates the other. When you want to “return” to the original state, the outermost doll gets removed first and then the 2nd last doll and so on and so forth.

This is the same as middleware. When a response is made, it returns from the bottom up.

So in order to capture the amended header from Rack::ContentLength, I need to make sure that my ResponseLogger returns only after Rack::ContentLength has been returned. To do that, I can use the config.middleware.insert_after option.

  # config/application.rb

  config.middleware.insert_before Rack::Sendfile, "ResponseLogger"
  config.middleware.use Rack::ContentLength

Why Rack::Sendfile? Because I want to grab the last response to make sure I don’t miss anything out. If you look at rake middleware you’ll notice that Rack::Sendfile is the first on the list. So if I want to capture whatever its returning, I need to initialize it before it.

Hope this helps!

References