How to generate a unique request ID in Rails?

Question

I need a unique request ID for my logger, so I can track each request in the log file.

So far I got this

REQUEST_ID = Digest::MD5.hexdigest(Time.now.to_f.to_s + $PID.to_s)

The problem is that I don't know where to put this. I tried placing it inside my custom logger file, outside the class. But it must be being cached or something because I'm always getting the same hash.

Any ideas?

note. I'm using Rails 3 and Passenger standalone

UPDATE:

Rails 3.2 :uuid tag won't work. Look how badly formatted the logs are:

[0909413851b79676cb06e0842d21c466] [127.0.0.1] 

Started HEAD "/" for 127.0.0.1 at Tue Feb 21 14:08:25 -0300 2012
[0909413851b79676cb06e0842d21c466] [127.0.0.1] Processing by PagesController#home as HTML
[0909413851b79676cb06e0842d21c466] [127.0.0.1] bla
[0909413851b79676cb06e0842d21c466] [127.0.0.1]   Rendered pages/home.html.erb within layouts/application (2.0ms)

In production this will be a mess. Notice the newlines after the first line? Now imagine how the logs would look like in a server handling many requests per second. It will be hard to associate a request with a URI

Answer 1

Rails core team took care of it for you!

Rails 3.2 introduces request.uuid method, which returns, um, unique request identifier, which looks like this: ab939dfca5d57843ea4c695cab6f721d.

See release notes here.

Also take a look at this awesome screencast to know how to use this new method with logging.

# config/environments/development.rb 
config.log_tags = [:uuid, :remote_ip]


# log file
[ab939dfca5d57843ea4c695cab6f721d] [127.0.0.1] 

Started GET "/" for 127.0.0.1 at 2012-01-27 21:52:58 +0000
[ab939dfca5d57843ea4c695cab6f721d] [127.0.0.1] Processing by ProductsController#index as HTML
[ab939dfca5d57843ea4c695cab6f721d] [127.0.0.1]   Product Load (0.3ms)  SELECT "products".* FROM "products" 
[ab939dfca5d57843ea4c695cab6f721d] [127.0.0.1]   Rendered products/index.html.erb within layouts/application (22.0ms)
[ab939dfca5d57843ea4c695cab6f721d] [127.0.0.1] Completed 200 OK in 81ms (Views: 73.1ms | ActiveRecord: 0.3ms)
[98eec5f8976586c1165b981797086b6a] [127.0.0.1] 

Answer 2

If you want to insert the request UUID at the log line Started GET "/" for 127.0.0.1 at Tue Feb 21 14:00:00 -0300 2012, you can patch or subclass Rails::Rack::Logger to modify the call_app method:

def call_app(env)
  request = ActionDispatch::Request.new(env)
  path = request.filtered_path
  Rails.logger.info "\n\nStarted #{request.request_method} \"#{path}\" for #{request.ip} at #{Time.now.to_default_s}"
  @app.call(env)
ensure
  ActiveSupport::LogSubscriber.flush_all!
end

The request object is created right before the logging statement, so you can change the logging statement to include request.uuid.

Answer 3

Follow-up to the answer using log_tags, since :uuid is only unique among a request, it is difficult to use it with session tracking.

I found log_tags accept a Proc, and pass a request object as an parameter. So, following code will stamp all of log entry with session_id (assuming you're using ActiveRecord based session store)

config.log_tags = [ lambda {|req| "#{req.cookie_jar["_session_id"]}" }, :remote_ip, :uuid  ]