From a8243ab15e818e43fc5fc864d67ab897cd9dfb44 Mon Sep 17 00:00:00 2001 From: hamir-suspect Date: Fri, 21 Nov 2025 15:58:23 +0100 Subject: [PATCH 1/4] chore: add more logging for user authentication --- ee/rbac/lib/rbac/utils/http.ex | 1 + .../lib/front_web/plugs/fetch_permissions.ex | 6 +++ .../lib/front_web/plugs/public_page_access.ex | 6 +++ guard/lib/guard/grpc_servers/auth_server.ex | 48 +++++++++++++++++-- guard/lib/guard/utils.ex | 1 + 5 files changed, 59 insertions(+), 3 deletions(-) diff --git a/ee/rbac/lib/rbac/utils/http.ex b/ee/rbac/lib/rbac/utils/http.ex index 2b76c8e8a..334b804fa 100644 --- a/ee/rbac/lib/rbac/utils/http.ex +++ b/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.warn("State key: #{key} not found in cookies") {:error, "State key: #{key} not found in cookies"} end end diff --git a/front/lib/front_web/plugs/fetch_permissions.ex b/front/lib/front_web/plugs/fetch_permissions.ex index 38ab18a89..a56b92301 100644 --- a/front/lib/front_web/plugs/fetch_permissions.ex +++ b/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) diff --git a/front/lib/front_web/plugs/public_page_access.ex b/front/lib/front_web/plugs/public_page_access.ex index 99f21a46b..a345c0c17 100644 --- a/front/lib/front_web/plugs/public_page_access.ex +++ b/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 diff --git a/guard/lib/guard/grpc_servers/auth_server.ex b/guard/lib/guard/grpc_servers/auth_server.ex index d2bb7bb23..14b5e7b96 100644 --- a/guard/lib/guard/grpc_servers/auth_server.ex +++ b/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,37 @@ 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 +136,47 @@ 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} + {: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), diff --git a/guard/lib/guard/utils.ex b/guard/lib/guard/utils.ex index 10a71851c..b9a254479 100644 --- a/guard/lib/guard/utils.ex +++ b/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 From 92d468cd3db6e92d083408969aabe5ec6662a6ba Mon Sep 17 00:00:00 2001 From: hamir-suspect Date: Fri, 21 Nov 2025 16:54:10 +0100 Subject: [PATCH 2/4] fix: linting --- ee/rbac/lib/rbac/store/user_permissions.ex | 4 +--- ee/rbac/test/rbac/grpc_servers/okta_server_test.exs | 6 ++---- ee/rbac/test/rbac/grpc_servers/rbac_server_test.exs | 3 +-- 3 files changed, 4 insertions(+), 9 deletions(-) diff --git a/ee/rbac/lib/rbac/store/user_permissions.ex b/ee/rbac/lib/rbac/store/user_permissions.ex index 6b3c60a30..96b5f4bb6 100644 --- a/ee/rbac/lib/rbac/store/user_permissions.ex +++ b/ee/rbac/lib/rbac/store/user_permissions.ex @@ -226,9 +226,7 @@ defmodule Rbac.Store.UserPermissions do RBI.generate_cache_key(rbi) end) - case @store_backend.put_batch(@user_permissions_store_name, keys, permissions, - timeout: 60_000 - ) do + case @store_backend.put_batch(@user_permissions_store_name, keys, permissions, timeout: 60_000) do {:ok, no_of_inserts} -> Logger.info("[User-Permissions Store] Batch inserted #{no_of_inserts} into the cache") :ok diff --git a/ee/rbac/test/rbac/grpc_servers/okta_server_test.exs b/ee/rbac/test/rbac/grpc_servers/okta_server_test.exs index f064435b0..392bcec23 100644 --- a/ee/rbac/test/rbac/grpc_servers/okta_server_test.exs +++ b/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 diff --git a/ee/rbac/test/rbac/grpc_servers/rbac_server_test.exs b/ee/rbac/test/rbac/grpc_servers/rbac_server_test.exs index ac0b04db1..44b845ed5 100644 --- a/ee/rbac/test/rbac/grpc_servers/rbac_server_test.exs +++ b/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) From 1a900fea7ffd0939db732f8243851a4d0c878598 Mon Sep 17 00:00:00 2001 From: hamir-suspect Date: Fri, 21 Nov 2025 16:54:28 +0100 Subject: [PATCH 3/4] fix: linting --- guard/lib/guard/grpc_servers/auth_server.ex | 20 +++++++++++++++----- 1 file changed, 15 insertions(+), 5 deletions(-) diff --git a/guard/lib/guard/grpc_servers/auth_server.ex b/guard/lib/guard/grpc_servers/auth_server.ex index 14b5e7b96..4a8ac4703 100644 --- a/guard/lib/guard/grpc_servers/auth_server.ex +++ b/guard/lib/guard/grpc_servers/auth_server.ex @@ -102,7 +102,10 @@ defmodule Guard.GrpcServers.AuthServer do {: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") + Logger.debug( + "[AuthServer] find_user_by_cookie user not found after session processing" + ) + {:error, :user, :not_found} {:error, :session_process_error} -> @@ -151,10 +154,14 @@ defmodule Guard.GrpcServers.AuthServer do 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}") + 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} + {: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)}" @@ -163,13 +170,16 @@ defmodule Guard.GrpcServers.AuthServer do {:error, :session_process_error} end else - Logger.debug("[AuthServer] process_session valid id=#{session_id} user_id=#{session.user_id}") + 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 + defp process_session(%{}, user_data, extras) do Logger.debug("[AuthServer] process_session no session_id, skipping") {:ok, user_data, extras} end From 3cca27d5b4f587a9cd8e51b6147ee7d46ed0ab34 Mon Sep 17 00:00:00 2001 From: hamir-suspect Date: Fri, 21 Nov 2025 17:15:41 +0100 Subject: [PATCH 4/4] fix: linting with new elixir version --- ee/rbac/lib/rbac/store/user_permissions.ex | 4 +++- ee/rbac/lib/rbac/utils/http.ex | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/ee/rbac/lib/rbac/store/user_permissions.ex b/ee/rbac/lib/rbac/store/user_permissions.ex index 96b5f4bb6..6b3c60a30 100644 --- a/ee/rbac/lib/rbac/store/user_permissions.ex +++ b/ee/rbac/lib/rbac/store/user_permissions.ex @@ -226,7 +226,9 @@ defmodule Rbac.Store.UserPermissions do RBI.generate_cache_key(rbi) end) - case @store_backend.put_batch(@user_permissions_store_name, keys, permissions, timeout: 60_000) do + case @store_backend.put_batch(@user_permissions_store_name, keys, permissions, + timeout: 60_000 + ) do {:ok, no_of_inserts} -> Logger.info("[User-Permissions Store] Batch inserted #{no_of_inserts} into the cache") :ok diff --git a/ee/rbac/lib/rbac/utils/http.ex b/ee/rbac/lib/rbac/utils/http.ex index 334b804fa..6c75522e4 100644 --- a/ee/rbac/lib/rbac/utils/http.ex +++ b/ee/rbac/lib/rbac/utils/http.ex @@ -57,7 +57,7 @@ defmodule Rbac.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") + Logger.warning("State key: #{key} not found in cookies") {:error, "State key: #{key} not found in cookies"} end end