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]

Solution 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 ...

Solution 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

Solution 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.

Solution 4

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

Solution 5

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}"
  }
]

View more solutions

Comments

[aceofspades]

I'm using github.com/roidrage/lograge for this

[boblin]

Thank's for reply. I tried your first example but it does not work for me. I get "Internal Server Error".

[Viktor Trón]

how about now? channge to req.env

[boblin]

There is also missing final ']', but I still get "Internal Server Error".

[rit]

@CharlesBergeron Did you figure out if this approach is ok or not?

[Chuck Bergeron]

@rit Yep, went with inserting our own custom logging Middleware like this: require_relative '../lib/my_app/log_user_id' config.middleware.insert_after(ActiveRecord::SessionStore, MyApp::LogUserId)

[rit]

@CharlesBergeron Thanks!

[Rafael Oliveira]

Best way to go. Thanks

[Fabio]

This is the cleanest approach.

[oligan]

Is "qnaire" short for "questionnaire"?

[Ali Guliyev]

@AndrewGrimm yes (-:

[mrstif]

Be mindful that this approach does not work properly when trying to change your cookie store options. your options will basically be discarded