chore: add more logging for user authentication (#726)

## 📝 Description
Verbose logging for user authentication process and 404s from front
service.

## ✅ Checklist
- [ ] I have tested this change
- [ ] This change requires documentation update

Author: hamir-suspect

ee/rbac/lib/rbac/utils/http.ex

@@ -57,6 +57,7 @@ defmodule Rbac.Utils.Http do
         {:ok, Plug.Crypto.non_executable_binary_to_term(encoded_state, [:safe]), conn}
 
       :error ->
+        Logger.warning("State key: #{key} not found in cookies")
         {:error, "State key: #{key} not found in cookies"}
     end
   end

ee/rbac/test/rbac/grpc_servers/okta_server_test.exs

@@ -601,8 +601,7 @@ defmodule Rbac.GrpcServers.OktaServer.Test do
       assert {:ok, response} = InternalApi.Okta.Okta.Stub.set_up_mapping(channel, request)
       assert %InternalApi.Okta.SetUpMappingResponse{} = response
 
-      {:ok, idp_mapping} =
-        Rbac.Okta.IdpGroupMapping.get_for_organization(integration.org_id)
+      {:ok, idp_mapping} = Rbac.Okta.IdpGroupMapping.get_for_organization(integration.org_id)
 
       assert length(idp_mapping.group_mapping) == 2
       assert length(idp_mapping.role_mapping) == 1
@@ -800,8 +799,7 @@ defmodule Rbac.GrpcServers.OktaServer.Test do
 
       assert {:ok, channel} = GRPC.Stub.connect("localhost:50051")
 
-      assert {:error, error} =
-               InternalApi.Okta.Okta.Stub.set_up_mapping(channel, initial_request)
+      assert {:error, error} = InternalApi.Okta.Okta.Stub.set_up_mapping(channel, initial_request)
 
       assert error.message =~ "Invalid"
     end

ee/rbac/test/rbac/grpc_servers/rbac_server_test.exs

@@ -616,8 +616,7 @@ defmodule Rbac.GrpcServers.RbacServer.Test do
 
       1..3
       |> Enum.each(fn i ->
-        {:ok, rbac_user} =
-          Support.Factories.RbacUser.insert(UUID.generate(), "John Doe #{i}")
+        {:ok, rbac_user} = Support.Factories.RbacUser.insert(UUID.generate(), "John Doe #{i}")
 
         Support.Rbac.assign_org_role_by_name(@org_id, rbac_user.id, Enum.at(roles, i - 1))
       end)

front/lib/front_web/plugs/fetch_permissions.ex

@@ -25,6 +25,12 @@ defmodule FrontWeb.Plugs.FetchPermissions do
     user_id = conn.assigns.user_id
     org_id = conn.assigns.organization_id
 
+    if is_nil(user_id) do
+      Logger.info(
+        "[FetchPermissions] Missing user_id while fetching permissions scope=#{scope} org_id=#{inspect(org_id)} path=#{conn.request_path}"
+      )
+    end
+
     has_permissions =
       if scope == "org" do
         Front.RBAC.Permissions.has?(user_id, org_id, permissions)

front/lib/front_web/plugs/public_page_access.ex

@@ -20,6 +20,12 @@ defmodule FrontWeb.Plugs.PublicPageAccess do
         Plug.Conn.assign(conn, :authorization, :guest)
 
       true ->
+        project = conn.assigns[:project]
+
+        Logger.info(
+          "[PageAccess] Anonymous/unauthorized access blocked: path=#{conn.request_path} org_id=#{inspect(conn.assigns[:organization_id])} project_id=#{inspect(project && project.id)} public?=#{inspect(project && project.public)} user_id=#{inspect(conn.assigns[:user_id])}"
+        )
+
         conn |> render_404()
     end
   rescue

guard/lib/guard/grpc_servers/auth_server.ex

@@ -24,12 +24,23 @@ defmodule Guard.GrpcServers.AuthServer do
   @spec authenticate_with_cookie(Auth.AuthenticateWithCookieRequest.t(), GRPC.Server.Stream.t()) ::
           Auth.AuthenticateResponse.t()
   def authenticate_with_cookie(%Auth.AuthenticateWithCookieRequest{cookie: cookie}, _stream) do
+    cookie_hash =
+      :crypto.hash(:md5, cookie)
+      |> Base.encode16(case: :lower)
+
+    Logger.debug("[AuthServer] authenticate_with_cookie start hash=#{cookie_hash}")
+
     observe("grpc.authentication.authenticate_with_cookie", fn ->
       case find_user_by_cookie(cookie) do
         {:ok, {user, id_provider, ip_address, user_agent}} ->
+          Logger.debug(
+            "[AuthServer] authenticate_with_cookie user_id=#{user.id} provider=#{id_provider} ip=#{ip_address}"
+          )
+
           respond_with_user(user, id_provider, ip_address, user_agent)
 
         {:error, :user, :not_found} ->
+          Logger.debug("[AuthServer] authenticate_with_cookie not found hash=#{cookie_hash}")
           respond_false()
       end
     end)
@@ -70,23 +81,40 @@ defmodule Guard.GrpcServers.AuthServer do
     end
   end
 
-  defp find_user_by_cookie(""), do: {:error, :user, :not_found}
+  defp find_user_by_cookie("") do
+    Logger.debug("[AuthServer] find_user_by_cookie empty cookie")
+    {:error, :user, :not_found}
+  end
 
   defp find_user_by_cookie(cookie) do
     case Guard.Session.deserialize_from_cookie(cookie) do
       {:ok, {id_provider, user_data, session_data, extras}} ->
+        Logger.debug(
+          "[AuthServer] find_user_by_cookie deserialized provider=#{id_provider} session_keys=#{inspect(Map.keys(session_data))} extras=#{inspect(Map.keys(extras))}"
+        )
+
         with {:ok, user_data, extras} <- process_session(session_data, user_data, extras),
              {:ok, user} <- get_user(user_data) do
+          Logger.debug(
+            "[AuthServer] find_user_by_cookie resolved user_id=#{user.id} provider=#{id_provider}"
+          )
+
           {:ok, {user, id_provider, extras.ip_address, extras.user_agent}}
         else
           {:error, :user_not_found} ->
+            Logger.debug(
+              "[AuthServer] find_user_by_cookie user not found after session processing"
+            )
+
             {:error, :user, :not_found}
 
           {:error, :session_process_error} ->
+            Logger.debug("[AuthServer] find_user_by_cookie session processing error")
             {:error, :user, :not_found}
         end
 
       {:error, :invalid_cookie} ->
+        Logger.debug("[AuthServer] find_user_by_cookie invalid cookie format")
         {:error, :user, :not_found}
     end
   end
@@ -111,30 +139,54 @@ defmodule Guard.GrpcServers.AuthServer do
           {:ok, Map.t(), Map.t()}
           | {:error, :session_process_error}
   defp process_session(%{id: session_id}, _, _) do
+    Logger.debug("[AuthServer] process_session OIDC id=#{session_id}")
+
     case Guard.Store.OIDCSession.get(session_id) do
       {:error, :not_found} ->
+        Logger.debug("[AuthServer] process_session session not found id=#{session_id}")
         {:error, :session_process_error}
 
       {:ok, %Guard.Repo.OIDCSession{refresh_token_enc: nil}} ->
+        Logger.debug("[AuthServer] process_session refresh_token missing id=#{session_id}")
         {:error, :session_process_error}
 
       {:ok, session} ->
         extras = %{ip_address: session.ip_address, user_agent: session.user_agent}
 
         if Guard.Store.OIDCSession.expired?(session) do
+          Logger.debug(
+            "[AuthServer] process_session expired id=#{session_id} user_id=#{session.user_id}"
+          )
+
           case refresh_session(session) do
-            {:ok, session} -> {:ok, %{id: session.user_id}, extras}
-            {:error, _} -> {:error, :session_process_error}
+            {:ok, session} ->
+              {:ok, %{id: session.user_id}, extras}
+
+            {:error, reason} ->
+              Logger.debug(
+                "[AuthServer] process_session refresh failed id=#{session_id} user_id=#{session.user_id} reason=#{inspect(reason)}"
+              )
+
+              {:error, :session_process_error}
           end
         else
+          Logger.debug(
+            "[AuthServer] process_session valid id=#{session_id} user_id=#{session.user_id}"
+          )
+
           {:ok, %{id: session.user_id}, extras}
         end
     end
   end
 
-  defp process_session(%{}, user_data, extras), do: {:ok, user_data, extras}
+  defp process_session(%{}, user_data, extras) do
+    Logger.debug("[AuthServer] process_session no session_id, skipping")
+    {:ok, user_data, extras}
+  end
 
   defp refresh_session(session) do
+    Logger.debug("[AuthServer] refresh_session id=#{session.id} user_id=#{session.user_id}")
+
     with {:ok, refresh_token} <-
            Guard.OIDC.Token.decrypt(session.refresh_token_enc, session.user_id),
          {:ok, tokens} <- refresh_token(refresh_token, session.user),

guard/lib/guard/utils.ex

@@ -226,6 +226,7 @@ defmodule Guard.Utils.Http do
         {:ok, Plug.Crypto.non_executable_binary_to_term(encoded_state, [:safe]), conn}
 
       :error ->
+        Logger.warn("State key: #{key} not found in cookies")
         {:error, "State key: #{key} not found in cookies"}
     end
   end