[LRUG] Logging session data

[Andrew Stewart]

Hello LRUG!

In my Rails app I try to tag each log line with the id of the signed-in user, like this:

  # config/environments/production.rb
  config.log_tags = [
    lambda { |request|
      session_key = Rails.application.config.session_options[:key]
      session_data = request.cookie_jar.signed[session_key]
      if session_data
        session_data['current_person_id'] || 'public'
      else
        'public-na'
      end
    }
  ]

Usually it works...but sometimes I see a signed-in user requesting a page and the log lines are tagged with "public" (never "public-na") instead of e.g. "42".

I can't figure out why current_person_id wouldn't be in session_data when the request hits the logger middleware, but would be once it reaches the controller.

I can't reproduce this reliably either.

I'm using Rails 3.2 with the cookie-based session store, and Unicorn with multiple workers.

My workaround is to tag log lines with the request's uuid instead, and add a before_filter to ApplicationController which logs the request uuid and the current_person_id:

  # config/environments/production.rb
  config.log_tags = [ :uuid ]

  # app/controllers/application_controller.rb
  class ApplicationController < ActionController::Base
    before_filter :log_request_uuid
    
    def log_request
      Rails.logger.info "Request #{request.uuid} :: person #{session['current_person_id'] || 'public'}"
    end
  end

Although the workaround works, I can't see why my first approach doesn't.  Can anyone offer enlightenment please?

Many thanks in advance,

Andy Stewart