Devise log after auth failure

Question

I need to write a log when somebody failes to log in to my app (to track bruteforce attempts). Also I decided to log successful authentications. So I created a SessionsController < Devise::SessionsController and tried to override the sessions#create method like that: https://gist.github.com/3884693

The first part works perfectly, but when the auth failes rails throws some kind of an exception and never reaches the if statement. So I don't know what to do.

Answer 1

This answer to a previous SO question - Devise: Registering log in attempts has the answer.

The create action in the devise controller calls warden.authenticate!, which attempts to authenticate the user with the supplied params. If authentication fails then authenticate! will call the devise failure app, which then runs the SessionsController#new action. Note, any filters you have for the create action will not run if authentication fails.

So the solution is to add a filter after the new action which checks the contents of env["warden.options"] and takes the appropriate action.

I tried out the suggestion, and was able to log both the successful & failed login attempts. Here is the relevant controller code:

class SessionsController < Devise::SessionsController
  after_filter :log_failed_login, :only => :new

  def create
    super
    ::Rails.logger.info "\n***\nSuccessful login with email_id : #{request.filtered_parameters["user"]}\n***\n"
  end

  private
  def log_failed_login
    ::Rails.logger.info "\n***\nFailed login with email_id : #{request.filtered_parameters["user"]}\n***\n" if failed_login?
  end 

  def failed_login?
    (options = env["warden.options"]) && options[:action] == "unauthenticated"
  end 
end

The log has the following entries:

For a successful login

Started POST "/users/sign_in"
...
...
***
Successful login with email_id : {"email"=>...
***
...
...
Completed 302 Found

For a failed login

Started POST "/users/sign_in"
...
...
Completed 401 Unauthorized 
Processing by SessionsController#new as HTML
...
...
***
Failed login with email_id : {"email"=>...
***
...
...
Completed 302 Found

Answer 2

Prakash's answer is helpful, but it's not ideal to rely on SessionsController#new to be run as a side effect. I believe this is cleaner:

class LogAuthenticationFailure < Devise::FailureApp
  def respond
    if request.env.dig('warden.options', :action) == 'unauthenticated'
      Rails.logger.info('...')
    end
    super
  end
end

...

Devise.setup do |config|

config.warden do |manager|
  manager.failure_app = LogAuthenticationFailure
end

---

Check out Graeme's answer if you'd prefer to hook into Warden's callbacks (Devise is implemented using Warden).

Answer 3

I had the same question but was unable to resolve it using the "warden.options" since, in my case, these were being cleared before redirecting to the sessions#new action. After looking into a few alternatives that I judged to be too brittle (because they involved extending some Devise classes and aliasing existing methods), I wound up using some callbacks provided by Warden. It works better for me because the callback is invoked inside the current request-response cycle and the parameters are all preserved in the env object.

These callbacks are named and appear to be designed to solve this and related problems. And they are documented!

Warden supports the following callbacks as of warden-1.2.3:

• after_set_user
• after_authentication (useful for logging successful sign ins)
• after_fetch (alias for after_set_user)
• before_failure (useful for logging failed sign ins - example below)
• after_failed_fetch
• before_logout
• on_request

Each callback is set directly on the Warden::Manager class (may be inside config/initializers/devise.rb). To track a failed authentication attempt I added this:

Warden::Manager.before_failure do |env, opts|
  email = env["action_dispatch.request.request_parameters"][:user] &&
          env["action_dispatch.request.request_parameters"][:user][:email]
  # unfortunately, the User object has been lost by the time 
  # we get here; so we take a db hit because I care to see 
  # if the email matched a user account in our system
  user_exists = User.where(email: email).exists?

  if opts[:message] == :unconfirmed
    # this is a special case for me because I'm using :confirmable
    # the login was correct, but the user hasn't confirmed their 
    # email address yet
    ::Rails.logger.info "*** Login Failure: unconfirmed account access: #{email}"
  elsif opts[:action] == "unauthenticated"
    # "unauthenticated" indicates a login failure
    if !user_exists
      # bad email:
      # no user found by this email address
      ::Rails.logger.info "*** Login Failure: bad email address given: #{email}"
    else
      # the user exists in the db, must have been a bad password
      ::Rails.logger.info "*** Login Failure: email-password mismatch: #{email}"
    end
  end
end

I expect that you could use the before_logout callback to track logout actions as well, but I haven't tested it. There appear to be prepend_ variants of the callbacks as well.

Answer 4

I've found another way to do this, if you want, for example, display a custom message if login fails.

In my job, if login fails we check the activity status (custom logic) and display a message, no matter if the login was correct or not.

After debug a little bit and read warden docs I know this now: Warden executes a throw(:warden, opts), so, according to ruby docs, a throw must be captured inside a catch block.

def create
  flash.clear
  login_result = catch(:warden) { super }
  return unless login_failed?(login_result)

  email = params[:user][:email]
  flash[:alert] = # here I call my service that calculates the message
  redirect_to new_user_session_path
end

def login_failed?(login_result)
  login_result.is_a?(Hash) && login_result.key?(:scope) && login_result.key?(:recall)
end

throw docs: https://ruby-doc.org/core-2.6.3/Kernel.html#method-i-throw

catch docs: https://ruby-doc.org/core-2.6.3/Kernel.html#method-i-catch

Answer 5

For logout logging, you need to catch the destroy event, so add the following to the Session controller (from the above answer):

before_filter :log_logout, :only => :destroy  #add this at the top with the other filters

def log_logout
     ::Rails.logger.info "*** Logging out : #{current_user.email} ***\n"  
end

Answer 6

Building on Prakash Murty's answer, I think the approach in this answer (https://stackoverflow.com/a/34816998/891359) is a cleaner way to log a succesfull login attempt. Instead of calling super, Devise offers a way to pass a block that is yielded before the view is rendered.

So instead of doing this:

class SessionsController < Devise::SessionsController
  def create
    super
    ::Rails.logger.info "\n***\nSuccessful login with email_id : #{request.filtered_parameters["user"]}\n***\n"
  end
end

It is cleaner to do:

class SessionsController < Devise::SessionsController
  def create
    super do |user|
      ::Rails.logger.info "\n***\nSuccessful login with email_id : #{user.email}\n***\n"
    end
  end
end