Devise log after auth failure

问题:

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.

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

回答2:

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

回答3:

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

回答4:

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