README.md

Devise / Warden Tagged logging

I wrote a middleware (actually two, but they do the same with different implementations) that logs information about signed in scopes in a Rails + Devise application. The solution works with multiple logins (like having a person logged both as an Admin and a User). I tested against Rails 4 and Devise HEAD, but it should work fine in any Rails 3 application.

This solution doesn't use the log_tags configuration option since it isn't very helpful when you need to retrieve information stored in cookies/session. That information isn't 'ready' when the Rails::Rack::Logger is executed, since it happens way down in the middleware chain.

Add one of the following implementations to your application load path and use the following configuration to add the middleware to your application stack:

# application.rb
config.app_middleware.insert_after("Warden::Manager", "Devise::TaggedLogging")

You logs will end up looking like this:

Started GET "/projects/1/users/1/02-2013" for 127.0.0.1 at 2013-02-23 13:42:56 -0300
  User Load (1.2ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 1 ORDER BY "users"."id" ASC LIMIT 1
[current user: 1] Processing by ReportsController#show as HTML
[current user: 1]   Parameters: {"project_id"=>"1", "user_id"=>"1", "month"=>"02-2013"}
[current user: 1]   Project Load (1.1ms)  SELECT "projects".* FROM "projects" WHERE "projects"."id" = $1 LIMIT 1  [["id", "1"]]
[current user: 1]   User Load (0.7ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1  [["id", "1"]]
[current user: 1]   Rendered reports/show.html.erb within layouts/application (189.8ms)
[current user: 1]   User Load (1.1ms)  SELECT "users".* FROM "users" ORDER BY "users"."name" ASC
[current user: 1]   Project Load (0.5ms)  SELECT "projects".* FROM "projects" ORDER BY "projects"."name" ASC
[current user: 1]   Rendered layouts/shared/_header.html.erb (15.4ms)
[current user: 1] Completed 200 OK in 1811ms (Views: 306.9ms | ActiveRecord: 5.9ms)

Beware that the first line doesn't have any related information since it's logged by Rails::Rack::Logger, where you don't have the session data yet.

tagged_logging_with_query.rb

module Devise
  class TaggedLogging
    def initialize(app)
      @app = app
    end

    def call(env)
      if logger.respond_to?(:tagged)
        logger.tagged(compute_devise_tags(env)) { @app.call(env) }
      else
        @app.call(env)
      end
    end

    private
    
    # `warden.user` returns an instance of your objects, so
    # hits the database (but this shouldn't be a issue with AR query cache).
    # It might be useful if you need to log any information about
    # your users that isn't stored in the session
    def compute_devise_tags(env)
      warden = env['warden']
      Devise.mappings.keys.map do |scope|
        if record = warden.user(scope: scope)
          ["current #{scope}", record.to_key].join(": ")
        end
      end.compact
    end

    def logger
      Rails.logger
    end
  end
end

tagged_logging_with_session.rb

module Devise
  class TaggedLogging
    def initialize(app)
      @app = app
    end

    def call(env)
      if logger.respond_to?(:tagged)
        logger.tagged(compute_devise_tags(env)) { @app.call(env) }
      else
        @app.call(env)
      end
    end

    private
    # This implementation uses a `internal` object from Warden API
    # that just read the session data and return an Array with
    # the record class, id and authenticable salt. This data
    # is produced by the `serialize_into_session` method,
    # See https://github.com/plataformatec/devise/blob/master/lib/devise/models/authenticatable.rb#L187-L189
    # for more information.
    def compute_devise_tags(env)
      serializer = Warden::SessionSerializer.new(env)

      Devise.mappings.keys.map do |scope|
        key = serializer.key_for(scope)

        if session_data = serializer.session[key]
          ["current #{scope}", session_data[1]].join(": ")
        end
      end.compact
    end

    def logger
      Rails.logger
    end
  end
end