How to log user_name in Rails?

Question

I use Devise in Rails 3. I want to see name of current_user in production.log.

I would like to configure rails like this:

config.log_tags = [:user_name]

Answer 1

For anyone using Redis::Store @fjuillen's answer looks like this:

redis = Redis::Store.new
redis.select 3 # only if you use a different database
result = redis.get req.cookie_jar["_session_id"]

tested on rails 4.

Answer 2

Unfortunately log tags are evaluated only once at the very beginning of request delegation (in Rails::Rack::Logger middleware). At this stage there is no controller so any current_user helper is not yet available. No warden or even session set up yet, but there is a cookiejar at least, so if you store your session_id there you could restore the session or log session_id instead directly.

config.log_tags = [ lambda { |req| req.cookie_jar["_session_id"].to_s } ]

I think the best alternative is to store username in the cookie directly at log_in, and destroy it with the session.

config.log_tags = [ lambda { |req| req.cookie_jar["user_name"] || 'Noone' } ]

NOT WORKING:

But if you use devise, it uses warden raack middleware, so env['warden'] should be available, so can you try?

config.log_tags = [ lambda { |req| user = req.env['warden'].user; user && user.name || 'Noone'; } ]

Even without warden, since you do have session available via env['rack.session'], if you store user id in session, you can do something like

config.log_tags = [ lambda { |req| user = User.find_by_id(req.env['rack.session']['user_id']); user && user.name || 'Noone'; }

Answer 3

As @viktortron has said in his answer at log_tags initialization time we have not a proper session objet available, but the session_id is in the request.

If you are using a _database session_store_, as it is my case, you can rebuild the session ad-hoc:

session = ActiveRecord::SessionStore::Session.find_by_session_id(request.cookie_jar["_session_id"])

This is how my log_tags are defined:

# config/initializers/rails_log.rb
def get_user_id(req)
  session = ActiveRecord::SessionStore::Session.find_by_session_id(req.cookie_jar["_session_id"])
  result = session ? session.data["user_id"] : 0

  "%07d" % result
end

log_tags = []
log_tags << lambda { |req| Time.now.strftime("%F %T.%L") }
log_tags << lambda { |req| req.uuid.first(8) }
log_tags << lambda { |req| get_user_id(req) }

Rails.configuration.log_tags = log_tags

The result is something like:

[2013-01-22 13:51:36.659] [e52435d1] [0036484] <the log line>

Answer 4

I found this little tricky but working solution.

Warden stores user information in session, but req.session is not available for logging.

So you must add this to config/application.rb

config.middleware.delete(ActionDispatch::Cookies)
config.middleware.delete(ActionDispatch::Session::CookieStore)
config.middleware.insert_before(Rails::Rack::Logger, ActionDispatch::Session::CookieStore)
config.middleware.insert_before(ActionDispatch::Session::CookieStore, ActionDispatch::Cookies)

Then create file config/initializers/logging.rb

Rails.configuration.log_tags = [
  proc do |req|
    if req.session["warden.user.user.key"].nil?
      "Anonym"
    else
      "user_id:#{req.session["warden.user.user.key"][0][0]}"
    end
  end
]

Now I see this for Anonymous:

[Anonym] Served asset ...

and this for user:

[user_id:1] Served asset ...

Answer 5

I used this solution from Wojtek Kruszewski: https://gist.github.com/WojtekKruszewski

I tweaked a little bit for my project to only include id, but basically the same.

# config/application.rb

config.log_tags = [
  ->(req){
    if user_id = WardenTaggedLogger.extract_user_id_from_request(req)
      user_id.to_s
    else
      "?"
    end
  }
]

And create this initializer

# initializers/warden_tagged_logger.rb

module WardenTaggedLogger
  def self.extract_user_id_from_request(req)
    session_key = Rails.application.config.session_options[:key]
    session_data = req.cookie_jar.encrypted[session_key]
    warden_data = session_data["warden.user.user.key"]
    warden_data[0][0]
    rescue
      nil
  end
end

Answer 6

I'm using Swards solution and it works like a charm. However using begin..rescue instead of Hash#has_key? is a performance killer

require 'benchmark/ips'

good_hash = { 'warden.user.admin_user.key' => [[1]]}
bad_hash = {}

Benchmark.ips do |x|
  x.report('begin+rescue good hash') { good_hash['warden.user.admin_user.key'][0][0] }
  x.report('has_key good hash') do
    good_hash.has_key?('warden.user.admin_user.key') &&
        good_hash['warden.user.admin_user.key'][0][0]
  end

  x.report('begin+rescue bad hash') { bad_hash['warden.user.admin_user.key'][0][0] rescue nil }
  x.report('has_key bad hash') do
    if bad_hash.has_key?('warden.user.admin_user.key')
      bad_hash['warden.user.admin_user.key'][0][0]
    end
  end

  # Compare the iterations per second of the various reports!
  x.compare!
end

Results speak for themselves

Comparison:
    has_key bad hash:  4870164.1 i/s
begin+rescue good hash:  3544134.7 i/s - 1.37x slower
   has_key good hash:  2127500.6 i/s - 2.29x slower
begin+rescue bad hash:     4468.2 i/s - 1089.95x slower