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

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 2

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

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 5

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 6

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.