FEATURE: add hidden setting for verbose auth token logging

This is only needed to debug auth token issues, will result in lots
of logging

app/models/user_auth_token.rb

@@ -22,6 +22,18 @@ class UserAuthToken < ActiveRecord::Base
       rotated_at: Time.zone.now
     )
     user_auth_token.unhashed_auth_token = token
+
+    if SiteSetting.verbose_auth_token_logging
+      UserAuthTokenLog.create!(
+        action: 'generate',
+        user_auth_token_id: user_auth_token.id,
+        user_id: info[:user_id],
+        user_agent: info[:user_agent],
+        client_ip: info[:client_ip],
+        auth_token: hashed_token
+      )
+    end
+
     user_auth_token
   end
 
@@ -37,16 +49,41 @@ class UserAuthToken < ActiveRecord::Base
                           (auth_token = :unhashed_token AND legacy)) AND created_at > :expire_before",
                           token: token, unhashed_token: unhashed_token, expire_before: expire_before)
 
-    if user_token &&
+    token_expired =
+       user_token &&
        user_token.auth_token_seen &&
        user_token.prev_auth_token == token &&
        user_token.prev_auth_token != user_token.auth_token &&
        user_token.rotated_at > 1.minute.ago
+
+    if token_expired || !user_token
+
+      if SiteSetting.verbose_auth_token_logging
+        UserAuthTokenLog.create(
+          action: "miss token",
+          user_id: user_token&.user_id,
+          auth_token: token,
+          user_agent: opts && opts[:user_agent],
+          client_ip: opts && opts[:client_ip]
+        )
+      end
+
       return nil
     end
 
     if mark_seen && user_token && !user_token.auth_token_seen && user_token.auth_token == token
       user_token.update_columns(auth_token_seen: true)
+
+      if SiteSetting.verbose_auth_token_logging
+        UserAuthTokenLog.create(
+          action: "seen token",
+          user_auth_token_id: user_token.id,
+          user_id: user_token.user_id,
+          auth_token: user_token.auth_token,
+          user_agent: opts && opts[:user_agent],
+          client_ip: opts && opts[:client_ip]
+        )
+      end
     end
 
     user_token
@@ -57,6 +94,12 @@ class UserAuthToken < ActiveRecord::Base
   end
 
   def self.cleanup!
+
+    if SiteSetting.verbose_auth_token_logging
+      UserAuthTokenLog.where('created_at < :time',
+            time: SiteSetting.maximum_session_age.hours.ago - ROTATE_TIME).delete_all
+    end
+
     where('rotated_at < :time',
           time: SiteSetting.maximum_session_age.hours.ago - ROTATE_TIME).delete_all
 
@@ -89,6 +132,18 @@ class UserAuthToken < ActiveRecord::Base
     if result.cmdtuples > 0
       reload
       self.unhashed_auth_token = token
+
+      if SiteSetting.verbose_auth_token_logging
+        UserAuthTokenLog.create(
+          action: "rotate",
+          user_auth_token_id: id,
+          user_id: user_id,
+          auth_token: auth_token,
+          user_agent: user_agent,
+          client_ip: client_ip
+        )
+      end
+
       true
     else
       false

app/models/user_auth_token_log.rb

@@ -0,0 +1,2 @@
+class UserAuthTokenLog < ActiveRecord::Base
+end

config/site_settings.yml

@@ -301,6 +301,9 @@ login:
   sso_allows_all_return_paths: false
   enable_sso_provider: false
   verbose_sso_logging: false
+  verbose_auth_token_logging:
+    hidden: true
+    default: false
   sso_url:
     default: ''
     regex: '^https?:\/\/.+[^\/]$'

db/migrate/20170213180857_add_user_auth_token_log.rb

@@ -0,0 +1,13 @@
+class AddUserAuthTokenLog < ActiveRecord::Migration
+  def change
+    create_table :user_auth_token_logs do |t|
+      t.string :action, null: false
+      t.integer :user_auth_token_id
+      t.integer :user_id
+      t.inet :client_ip
+      t.string :user_agent
+      t.string :auth_token
+      t.datetime :created_at
+    end
+  end
+end

lib/auth/default_current_user_provider.rb

@@ -44,7 +44,11 @@ class Auth::DefaultCurrentUserProvider
       limiter = RateLimiter.new(nil, "cookie_auth_#{request.ip}", COOKIE_ATTEMPTS_PER_MIN ,60)
 
       if limiter.can_perform?
-        @user_token = UserAuthToken.lookup(auth_token, seen: true)
+        @user_token = UserAuthToken.lookup(auth_token,
+                                           seen: true,
+                                           user_agent: @env['HTTP_USER_AGENT'],
+                                           client_ip: @request.ip)
+
         current_user = @user_token.try(:user)
       end
 

spec/models/user_auth_token_spec.rb

@@ -4,6 +4,8 @@ describe UserAuthToken do
 
   it "can remove old expired tokens" do
 
+    SiteSetting.verbose_auth_token_logging = true
+
     freeze_time Time.zone.now
     SiteSetting.maximum_session_age = 1
 
@@ -120,4 +122,66 @@ describe UserAuthToken do
     end
   end
 
+  it "can correctly log auth tokens" do
+    SiteSetting.verbose_auth_token_logging = true
+
+    user = Fabricate(:user)
+
+    token = UserAuthToken.generate!(user_id: user.id,
+                                    user_agent: "some user agent",
+                                    client_ip: "1.1.2.3")
+
+    expect(UserAuthTokenLog.where(
+      action: 'generate',
+      user_id: user.id,
+      user_agent: "some user agent",
+      client_ip: "1.1.2.3",
+      user_auth_token_id: token.id,
+    ).count).to eq(1)
+
+    UserAuthToken.lookup(token.unhashed_auth_token,
+      seen: true,
+      user_agent: "something diff",
+      client_ip: "1.2.3.3"
+    )
+
+    UserAuthToken.lookup(token.unhashed_auth_token,
+      seen: true,
+      user_agent: "something diff2",
+      client_ip: "1.2.3.3"
+    )
+
+    expect(UserAuthTokenLog.where(
+      action: "seen token",
+      user_id: user.id,
+      auth_token: token.auth_token,
+      client_ip: "1.2.3.3",
+      user_auth_token_id: token.id
+    ).count).to eq(1)
+
+    fake_token = SecureRandom.hex
+    UserAuthToken.lookup(fake_token, seen: true, user_agent: "bob", client_ip: "127.0.0.1")
+
+    expect(UserAuthTokenLog.where(
+      action: "miss token",
+      auth_token: UserAuthToken.hash_token(fake_token),
+      user_agent: "bob",
+      client_ip: "127.0.0.1"
+    ).count).to eq(1)
+
+
+    freeze_time(UserAuthToken::ROTATE_TIME.from_now)
+
+    token.rotate!(user_agent: "firefox", client_ip: "1.1.1.1")
+
+    expect(UserAuthTokenLog.where(
+      action: "rotate",
+      auth_token: token.auth_token,
+      user_agent: "firefox",
+      client_ip: "1.1.1.1",
+      user_auth_token_id: token.id
+    ).count).to eq(1)
+
+  end
+
 end