Temporary additional logging to continue debugging MFA issues

app/controllers/concerns/authentication.rb

@@ -16,12 +16,19 @@ module Authentication
 
   private
     def authenticate_user!
+      Rails.logger.info "Authentication#authenticate_user! - Checking for session cookie"
+
       if session_record = find_session_by_cookie
+        Rails.logger.info "Authentication#authenticate_user! - Found valid session: #{session_record.id} for user: #{session_record.user_id}"
         Current.session = session_record
       else
+        Rails.logger.info "Authentication#authenticate_user! - No valid session found"
+
         if self_hosted_first_login?
+          Rails.logger.info "Authentication#authenticate_user! - Self-hosted first login detected, redirecting to registration"
           redirect_to new_registration_url
         else
+          Rails.logger.info "Authentication#authenticate_user! - Redirecting to login page"
           redirect_to new_session_url
         end
       end
@@ -29,21 +36,35 @@ module Authentication
 
     def find_session_by_cookie
       cookie_value = cookies.signed[:session_token]
-      Rails.logger.info "Looking for session with cookie value: #{cookie_value.present? ? 'present' : 'missing'}"
+      Rails.logger.info "Authentication#find_session_by_cookie - Looking for session with cookie value: #{cookie_value.present? ? 'present' : 'missing'}"
+
+      if cookie_value.present?
         session = Session.find_by(id: cookie_value)
-      Rails.logger.info "Session found: #{session.present? ? 'yes' : 'no'}"
+        Rails.logger.info "Authentication#find_session_by_cookie - Session found: #{session.present? ? 'yes' : 'no'}"
+
+        if session.present?
+          Rails.logger.info "Authentication#find_session_by_cookie - Session belongs to user: #{session.user_id}"
+        end
+
         session
+      else
+        Rails.logger.info "Authentication#find_session_by_cookie - No session cookie found"
+        nil
+      end
     end
 
     def create_session_for(user)
+      Rails.logger.info "Authentication#create_session_for - Creating session for user: #{user.id}"
       session = user.sessions.create!
-      Rails.logger.info "Setting session cookie with value: #{session.id}"
-      # Explicitly set SameSite attribute and ensure cookie is set properly
-      cookies.signed.permanent[:session_token] = {
-        value: session.id,
-        httponly: true,
-        same_site: :lax
-      }
+      Rails.logger.info "Authentication#create_session_for - Session created with ID: #{session.id}"
+
+      Rails.logger.info "Authentication#create_session_for - Setting session cookie"
+      cookies.signed.permanent[:session_token] = { value: session.id, httponly: true }
+
+      Rails.logger.info "Authentication#create_session_for - Cookie set, verifying..."
+      cookie_value = cookies.signed[:session_token]
+      Rails.logger.info "Authentication#create_session_for - Cookie verification: #{cookie_value == session.id ? 'successful' : 'failed'}"
+
       session
     end
 

app/controllers/mfa_controller.rb

@@ -3,50 +3,74 @@ class MfaController < ApplicationController
   skip_authentication only: [ :verify, :verify_code ]
 
   def new
+    Rails.logger.info "MfaController#new - User: #{Current.user.id} accessing MFA setup"
     redirect_to root_path if Current.user.otp_required?
     Current.user.setup_mfa! unless Current.user.otp_secret.present?
   end
 
   def create
+    Rails.logger.info "MfaController#create - User: #{Current.user.id} attempting to enable MFA"
     if Current.user.verify_otp?(params[:code])
+      Rails.logger.info "MfaController#create - MFA verification successful for user: #{Current.user.id}"
       Current.user.enable_mfa!
       @backup_codes = Current.user.otp_backup_codes
+      Rails.logger.info "MfaController#create - Generated backup codes for user: #{Current.user.id}"
       render :backup_codes
     else
+      Rails.logger.info "MfaController#create - MFA verification failed for user: #{Current.user.id}"
       Current.user.disable_mfa!
       redirect_to new_mfa_path, alert: t(".invalid_code")
     end
   end
 
   def verify
+    Rails.logger.info "MfaController#verify - Attempting to verify MFA for user_id from session: #{session[:mfa_user_id]}"
     @user = User.find_by(id: session[:mfa_user_id])
-    redirect_to new_session_path unless @user
+
+    if @user
+      Rails.logger.info "MfaController#verify - Found user: #{@user.id} for MFA verification"
+    else
+      Rails.logger.info "MfaController#verify - No user found for MFA verification, redirecting to login"
+      redirect_to new_session_path
+    end
   end
 
   def verify_code
+    Rails.logger.info "MfaController#verify_code - Attempting to verify MFA code for user_id from session: #{session[:mfa_user_id]}"
     @user = User.find_by(id: session[:mfa_user_id])
 
-    if @user&.verify_otp?(params[:code])
-      session.delete(:mfa_user_id)
-      @session = create_session_for(@user)
-      Rails.logger.info "MFA verification successful for user #{@user.id}. Session created: #{@session.id}"
-
-      # Explicitly set the cookie again to ensure it's properly set
-      cookies.signed.permanent[:session_token] = {
-        value: @session.id,
-        httponly: true,
-        same_site: :lax
-      }
-
-      # Use turbo: false to ensure a full page reload
-      redirect_to root_path, turbo: false
+    if @user
+      Rails.logger.info "MfaController#verify_code - Found user: #{@user.id} for MFA verification"
     else
+      Rails.logger.info "MfaController#verify_code - No user found for MFA verification"
+    end
+
+    if @user&.verify_otp?(params[:code])
+      Rails.logger.info "MfaController#verify_code - MFA code verification successful for user: #{@user.id}"
+      session.delete(:mfa_user_id)
+      Rails.logger.info "MfaController#verify_code - Deleted mfa_user_id from session"
+
+      @session = create_session_for(@user)
+      Rails.logger.info "MfaController#verify_code - Created session: #{@session.id} for user: #{@user.id}"
+
+      # Log cookie information
+      Rails.logger.info "MfaController#verify_code - Cookie details:"
+      Rails.logger.info "  - session_token present: #{cookies.signed[:session_token].present?}"
+      Rails.logger.info "  - session_token value: #{cookies.signed[:session_token]}"
+      Rails.logger.info "  - all cookies: #{cookies.to_h.keys.join(', ')}"
+
+      # Simply redirect to root path with data-turbo="false"
+      Rails.logger.info "MfaController#verify_code - Redirecting to root_path with data-turbo=false"
+      redirect_to root_path, data: { turbo: false }
+    else
+      Rails.logger.info "MfaController#verify_code - MFA code verification failed for user: #{@user&.id}"
       flash.now[:alert] = t(".invalid_code")
       render :verify, status: :unprocessable_entity
     end
   end
 
   def disable
+    Rails.logger.info "MfaController#disable - User: #{Current.user.id} disabling MFA"
     Current.user.disable_mfa!
     redirect_to settings_security_path, notice: t(".success")
   end

app/controllers/sessions_controller.rb

@@ -5,24 +5,34 @@ class SessionsController < ApplicationController
   layout "auth"
 
   def new
+    Rails.logger.info "SessionsController#new - Rendering login form"
   end
 
   def create
+    Rails.logger.info "SessionsController#create - Attempting to authenticate user with email: #{params[:email]}"
+
     if user = User.authenticate_by(email: params[:email], password: params[:password])
+      Rails.logger.info "SessionsController#create - Authentication successful for user: #{user.id}"
+
       if user.otp_required?
+        Rails.logger.info "SessionsController#create - MFA required for user: #{user.id}, redirecting to MFA verification"
         session[:mfa_user_id] = user.id
         redirect_to verify_mfa_path
       else
+        Rails.logger.info "SessionsController#create - MFA not required for user: #{user.id}, creating session"
         @session = create_session_for(user)
+        Rails.logger.info "SessionsController#create - Session created: #{@session.id}, redirecting to root_path"
         redirect_to root_path
       end
     else
+      Rails.logger.info "SessionsController#create - Authentication failed for email: #{params[:email]}"
       flash.now[:alert] = t(".invalid_credentials")
       render :new, status: :unprocessable_entity
     end
   end
 
   def destroy
+    Rails.logger.info "SessionsController#destroy - Destroying session: #{@session.id} for user: #{Current.user.id}"
     @session.destroy
     redirect_to new_session_path, notice: t(".logout_successful")
   end