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

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 2

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 3

Added 2013-03-07:

In Rails 4 encrypted_cookie_store is the default session store. This is how you can access session data:

session_data = req.cookie_jar.signed[ "_qnaire_session" ]

And it looks like warden_data looks differently in my new app, e.g.: [[542], "$2a$10$e5aYxr/PIp6OOj8jzE7mke"], where first item is user id.

Here's my current snippet: https://gist.github.com/wojt-eu/5109643

Previous version:

This is what I came up with:

config.log_tags = [
  :remote_ip,
  ->(req){
    session_data = req.cookie_jar.signed[ "_qnaire_session" ]
    warden_data = session_data["warden.user.provider_user.key"]
    if warden_data
      '#' + warden_data[1][0].to_s
    else
      "guest"
    end
  }
]

_qnaire_session can be replaced with instance.config.session_options[:key] or via singleton: Rails.application.config.session_options[:key]

I have ProviderUser model, hence warden.user.provider_user.key. I suppose with User model this would be warden.user.user.key.

It's messy, but it does not affect normal authentication process, middleware stack order etc. If it breaks during some update only tagging logs will be affected, which I should quickly notice while looking at development logs.

Answer 4

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 5

Here's what I just added to config/initializers/logging.rb:

Rails.configuration.log_tags = [
  :uuid,   # request UUID
  lambda { |req|
    # Credentials are (currently) in the format of:
    #
    #   <session_hash>::<user_id>
    #
    # So we have to split by '::' to obtain the user_id for logging.
    #
    # This will just output "User: nil" if there is no current session.
    "User: #{req.cookies['user_credentials'].to_s.split('::')[1]}"
  }
]

This is for Authlogic. What you need to do might vary, so you should really dig in and see what your data exposes to you already.

Step 1:

See what the req object has available. Add this to config/initializers/logging.rb:

Rails.configuration.log_tags = [
  lambda { |req|
    req.inspect
  }
]

Then hit a page, and see what gets dumped.

Step 2: See if your cookie jar has enough information, using the same technique:

Rails.configuration.log_tags = [
  lambda { |req|
    req.cookies.inspect
  }
]

(hit a request)

An aside: Don't worry about putting in usernames/emails into the logs - user ID is good enough, and you can look it up in the database to get any extra metadata you need.

Answer 6

Here is the cookie decrypter I use in Rails 5.1 to tag the logs with the user_id, which is stored in the cookie. It basically lets me access the controller equivalent of session[:user_id] from a raw cookie

environments/production.rb:

config.log_tags = [
  :request_id,
  :remote_ip,
  lambda do |req|
    session_data = CookieDecrypter.new(req).session_data
    "user_id:#{session_data['user_id']}"
  end
]

app/models/cookie_decrypter.rb:

class CookieDecrypter
  attr_reader :request

  def initialize(request)
    @request = request
  end

  def session_data
    cookie = request.cookies[session_key]
    return {} unless cookie.present?
    cookie = CGI::unescape(cookie)
    key_generator = ActiveSupport::KeyGenerator.new(secret_key_base, iterations: 1000)
    secret = key_generator.generate_key(salt)[0, ActiveSupport::MessageEncryptor.key_len]
    sign_secret = key_generator.generate_key(signed_salt)
    encryptor = ActiveSupport::MessageEncryptor.new(secret, sign_secret, serializer: JSON)
    encryptor.decrypt_and_verify(cookie) || {}
  end

  private

  def session_key
    Rails.application.config.session_options[:key]
  end

  def secret_key_base
    Rails.application.secrets[:secret_key_base]
  end

  def salt
    Rails.application.config.action_dispatch.encrypted_cookie_salt
  end

  def signed_salt
    Rails.application.config.action_dispatch.encrypted_signed_cookie_salt
  end
end

Answer 7

And Now for Something Completely Different...

https://github.com/roidrage/lograge/issues/23#issuecomment-11709861

I just tried this with Rails 4, latest Devise and Lograge.

Answer 8

What almost worked for me (Rails 3.2.22.2) is the answer from here: http://benjit.com/rails/logger/2016/02/26/getting-admin-user-into-rails-logfile/

This assumes that the cookie_jar object responds to encrypted. However it wasn't the case for me. What ultimately worked for me is as follows:

config/initializers/logging.rb:

Rails.configuration.log_tags = [
  lambda { |req|
    session_key = Rails.application.config.session_options[:key]
    session_data = req.cookie_jar.signed[Rails.application.config.session_options[:key] ]
    warden_data = ( session_data["warden.user.user.key"]|| [[]])
    admin_user = warden_data[0][0]
    "u: #{admin_user || 0}"
  }
]

Answer 9

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 10

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

Answer 11

As a quick and ugly workaround, maybe one could log a second line after the request has been processed.

This 500 ServerError has been presented by: #{username}

Answer 12

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.