How do I prepend a session-id to every log message (Rails 3)?

Question

My thinking is to capture the session_id and store it in thread local storage, e.g.

Thread.current[:session_id] = session[:session_id]

But some rails logging occurs before my filter is called.

I thought I might capture the session_id by writing a middleware plug-in. But again, I don't seem to get it early enough for all logging.

What is the earliest that I can capture session_id?

Thanks!

Answer 1

Since Rails 3.2 support tagged logging using log_tags configuration array, log_tags array accept a Proc object, and the proc object is invoked with a request object, I could configure the log_tags following way:

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

It's working with Rails 3.2.3, with ActiveRecord's session store is in use.

Answer 2

Okay, I finally figured this out.

1. I moved ActionDispatch::Cookies and ActionDispatch::Session::CookieStore way earlier in the rack stack. This appears to be safe, and is necessary because otherwise some logging happens before the session is initialized.

2. I added my own rack middleware component that sets the session_id in thread local storage.

3. I override the rails logger and prepend the session_id to each log message.

This is very helpful in being able to separate out and analyze all logs for particular user session.

I'd be interested to know how anyone else accomplishes this.

Answer 3

Based on @Felix's answer. i've done these in rails 4:

# config/application.rb
config.middleware.delete "ActionDispatch::Cookies"
config.middleware.delete "ActionDispatch::Session::CookieStore"
config.middleware.insert_before Rails::Rack::Logger, ActionDispatch::Cookies
config.middleware.insert_before Rails::Rack::Logger, ActionDispatch::Session::CookieStore

# config/environment/development.rb and production.rb
config.log_tags = [
  lambda {|req| "#{req.subdomain}/#{req.session["user_id"]}" },
  :uuid
]
config.log_formatter = Logger::Formatter.new

This produces logs like this:

I, [2015-11-05T15:45:42.617759 #22056]  INFO -- : [verimor/2] [77e593dc-c852-4102-a999-5c90ea0c9d66] Started GET "/home/dashboard" for 192.168.1.37 at 2015-11-05 15:45:42 +0200

[verimor/2] is subdomain/user_id (this is a multitenant app).

[77e593dc-c852-4102-a999-5c90ea0c9d66] is a unique id for this request. Useful for keeping track of the lifecycle of requests.

HTH.