CODEWITHSUNDEEP
ruby-on-rails-3sessionlogging
Felix Livni
Felix Livni

Reputation: 1244

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

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!

Upvotes: 5

Views: 3400

Answers (4)

Fatih
Fatih

Reputation: 308

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.

Upvotes: 2

jBilbo
jBilbo

Reputation: 1703

For Rails 3.2 with ActiveSupport::TaggedLogging, if you're using :cookie_store:

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

Note: Change the "_session_id" with your :key value at config/initializers/session_store.rb

Related: https://stackoverflow.com/a/22487360/117382

Upvotes: 1

shigeya
shigeya

Reputation: 4922

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.

Upvotes: 5

Felix Livni
Felix Livni

Reputation: 1244

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.

Upvotes: 2

Related Questions