Digging into Rails Logger

I feel log files are very important for debugging purposes. So I was curious to know how exactly the log files were getting filled in Rails.

How and where exactly does this get populated in the log file :

Started GET "/session/new" for 127.0.0.1 at 2013-11-23 14:51:42 +0530

This is what I found after a bit of digging.

When you run

rake middleware

on your rails app, you will see a list of middlewares being used in your Rails app. Some of them are by default, some you can opt in/out based on your configuration settings in your environment file (Example /environment/development.rb for dev environment)

Some of the middlewares used in my Rails app are :

  1. ActionDispatch::Static
  2. Rack::Lock
  3. ActiveSupport::Cache::Strategy::LocalCache::Middleware
  4. Rack::Runtime
  5. Rack::MethodOverride
  6. ActionDispatch::RequestId
  7. Rails::Rack::Logger
  8. ActionDispatch::ShowExceptions
  9. ActionDispatch::DebugExceptions
  10. ActionDispatch::RemoteIp
  11. ActionDispatch::Reloader
  12. ActionDispatch::Callbacks
  13. ActionDispatch::Cookies
  14. ActionDispatch::Session::CookieStore
  15. ActionDispatch::Flash
  16. ActionDispatch::ParamsParser
  17. Rack::Head
  18. Rack::ConditionalGet
  19. Rack::ETag
  20. Rack::Mongoid::Middleware::IdentityMap
  21. Hackerbox::Application.routes

Take a note of middleware no. 7.

Rails::Rake::Logger

The code for the Logger is in /railties/lib/rails/rack/logger.rb in the rails codebase.

Since its a rack middleware, it has a #call function.

      def call(env)
        request = ActionDispatch::Request.new(env)

        if Rails.logger.respond_to?(:tagged)
          Rails.logger.tagged(compute_tags(request)) do
              call_app(request, env) 
          end
        else
          call_app(request, env)
        end
      end

What the above code does is, it first builds the request. Then if in your environment file, If you have enabled log tagging this way,

config.log_tags = [ :uuid ]

Rails.logger.respond_to?(:tagged) would evaluate to true.

Lets take a look at compute_tags function

def compute_tags(request)  
    @taggers.collect do |tag|
        case tag    
        when Proc
            tag.call(request)
        when Symbol
            request.send(tag)
        else
            tag
        end
    end
end  

what this does is, it allows for an array of Procs/Symbols/Strings, example :

config.log_tags = [ Proc.new{"testing with procs "}, :uuid ]

This results in log files having lines like

[testing with procs   ] [8f6af83f-9f86-41b4-9045-c282b79d1b28] Started GET "/dashboard" for 127.0.0.1 at 2013-11-23 22:28:53 +0530

Now getting to the heart of the log, from where the main content is written to the log file

#Started GET "/session/new" for 127.0.0.1 at 2012-09-26 14:51:42 -0700
      def started_request_message(request)
        'Started %s "%s" for %s at %s' % [
          request.request_method,
          request.filtered_path,
          request.ip,
          Time.now.to_default_s ]
      end

This is how the log files are populated.

But I have one question in mind. As you saw from the code, request is sent accross as a parameter to multiple functions within the Logger class. Would it make for a good refactor to make request an instance variable, and then access it from methods via an accessor, without having to pass it around to multiple functions.

Let me know what you think about it.

Murtuza Kutub

Read more posts by this author.

Chennai, India

Subscribe to Murtuza's Blog

Get the latest posts delivered right to your inbox.

or subscribe via RSS with Feedly!