improvement(AuthenticationFailed): store a caused_by value in authentication failures. (#145)

This allows for a better debugging experience when trying to understand why an authentication action is failing.

Closes #128.

config/dev.exs

@@ -54,3 +54,5 @@ config :ash_authentication,
       signing_secret: "Marty McFly in the past with the Delorean"
     ]
   ]
+
+# config :ash_authentication, debug_authentication_failures?: true

lib/ash_authentication/application.ex

@@ -7,6 +7,8 @@ defmodule AshAuthentication.Application do
   @doc false
   @impl true
   def start(_type, _args) do
+    AshAuthentication.Debug.start()
+
     []
     |> maybe_append(
       start_dev_server?(),

lib/ash_authentication/debug.ex

@@ -0,0 +1,65 @@
+defmodule AshAuthentication.Debug do
+  @moduledoc """
+  Allows you to debug authentication failures in development.
+
+  Simply add `config :ash_authentication, debug_authentication_failures?: true`
+  to your `dev.exs` and get fancy log messages when authentication fails.
+  """
+
+  alias AshAuthentication.Errors.AuthenticationFailed
+  require Logger
+  import AshAuthentication.Utils
+
+  @doc false
+  @spec start :: :ok
+  def start do
+    if enabled?() do
+      Logger.warning("""
+      Starting AshAuthentication with `debug_authentication_failres?` turned on.
+
+      You should only ever do this in your development environment for
+      debugging purposes as it will leak PII into your log.
+
+      If you do not want this on then please remove the following line from
+      your configuration:
+
+          config :ash_authentication, debug_authentication_failures?: true
+      """)
+    end
+
+    :ok
+  end
+
+  @doc false
+  @spec describe(value) :: value when value: any
+  def describe(auth_failed) when is_struct(auth_failed, AuthenticationFailed) do
+    if enabled?() do
+      message =
+        case auth_failed.caused_by do
+          exception when is_exception(exception) -> Exception.message(exception)
+          %{message: message} -> message
+          _ -> "Unknown reason"
+        end
+
+      Logger.warning("""
+      Authentication failed: #{message}
+
+      Details: #{inspect(auth_failed, limit: :infinity, printable_limit: :infinity, pretty: true)}
+      """)
+    end
+
+    auth_failed
+  end
+
+  def describe(other), do: other
+
+  @doc """
+  Has authentication debug logging been enabled?
+  """
+  @spec enabled? :: boolean
+  def enabled? do
+    :ash_authentication
+    |> Application.get_env(:debug_authentication_failures?, false)
+    |> is_truthy()
+  end
+end

lib/ash_authentication/errors/authentication_failed.ex

@@ -3,10 +3,17 @@ defmodule AshAuthentication.Errors.AuthenticationFailed do
   A generic, authentication failed error.
   """
   use Ash.Error.Exception
-  def_ash_error([], class: :forbidden)
+  def_ash_error([caused_by: %{}], class: :forbidden)
+  import AshAuthentication.Debug
 
   @type t :: Exception.t()
 
+  def exception(args) do
+    args
+    |> super()
+    |> describe()
+  end
+
   defimpl Ash.ErrorKind do
     @moduledoc false
     def id(_), do: Ecto.UUID.generate()

lib/ash_authentication/strategies/oauth2/actions.ex

@@ -34,8 +34,47 @@ defmodule AshAuthentication.Strategy.OAuth2.Actions do
     |> Query.for_read(strategy.sign_in_action_name, params)
     |> api.read(options)
     |> case do
-      {:ok, [user]} -> {:ok, user}
-      _ -> {:error, Errors.AuthenticationFailed.exception([])}
+      {:ok, [user]} ->
+        {:ok, user}
+
+      {:ok, []} ->
+        {:error,
+         Errors.AuthenticationFailed.exception(
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned no users"
+           }
+         )}
+
+      {:ok, _users} ->
+        {:error,
+         Errors.AuthenticationFailed.exception(
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned too many users"
+           }
+         )}
+
+      {:error, error} when is_struct(error, Errors.AuthenticationFailed) ->
+        {:error, error}
+
+      {:error, error} when is_exception(error) ->
+        {:error, Errors.AuthenticationFailed.exception(caused_by: error)}
+
+      {:error, error} ->
+        {:error,
+         Errors.AuthenticationFailed.exception(
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned error: #{inspect(error)}"
+           }
+         )}
     end
   end
 

lib/ash_authentication/strategies/oauth2/sign_in_preparation.ex

@@ -10,7 +10,7 @@ defmodule AshAuthentication.Strategy.OAuth2.SignInPreparation do
     3. Updates the user identity resource, if one is enabled.
   """
   use Ash.Resource.Preparation
-  alias Ash.{Error.Framework.AssumptionFailed, Query, Resource.Preparation}
+  alias Ash.{Query, Resource.Preparation}
   alias AshAuthentication.{Errors.AuthenticationFailed, Info, Jwt, UserIdentity}
   require Ash.Query
   import AshAuthentication.Utils, only: [is_falsy: 1]
@@ -22,7 +22,14 @@ defmodule AshAuthentication.Strategy.OAuth2.SignInPreparation do
     case Info.strategy_for_action(query.resource, query.action.name) do
       :error ->
         {:error,
-         AssumptionFailed.exception(message: "Strategy is missing from the changeset context.")}
+         AuthenticationFailed.exception(
+           query: query,
+           caused_by: %{
+             module: __MODULE__,
+             action: query.action,
+             message: "Unable to infer strategy"
+           }
+         )}
 
       {:ok, strategy} ->
         query
@@ -33,7 +40,16 @@ defmodule AshAuthentication.Strategy.OAuth2.SignInPreparation do
             end
 
           _, _ ->
-            {:error, AuthenticationFailed.exception(query: query)}
+            {:error,
+             AuthenticationFailed.exception(
+               query: query,
+               caused_by: %{
+                 module: __MODULE__,
+                 action: query.action,
+                 strategy: strategy,
+                 message: "Query should return a single user"
+               }
+             )}
         end)
     end
   end

lib/ash_authentication/strategies/password/actions.ex

@@ -27,8 +27,44 @@ defmodule AshAuthentication.Strategy.Password.Actions do
     |> Query.for_read(strategy.sign_in_action_name, params)
     |> api.read(options)
     |> case do
-      {:ok, [user]} -> {:ok, user}
-      _ -> {:error, Errors.AuthenticationFailed.exception([])}
+      {:ok, [user]} ->
+        {:ok, user}
+
+      {:ok, []} ->
+        {:error,
+         Errors.AuthenticationFailed.exception(
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned no users"
+           }
+         )}
+
+      {:ok, _users} ->
+        {:error,
+         Errors.AuthenticationFailed.exception(
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned too many users"
+           }
+         )}
+
+      {:error, error} when is_exception(error) ->
+        {:error, Errors.AuthenticationFailed.exception(caused_by: error)}
+
+      {:error, error} ->
+        {:error,
+         Errors.AuthenticationFailed.exception(
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned error: #{inspect(error)}"
+           }
+         )}
     end
   end
 

lib/ash_authentication/strategies/password/sign_in_preparation.ex

@@ -36,16 +36,48 @@ defmodule AshAuthentication.Strategy.Password.SignInPreparation do
              Map.get(record, strategy.hashed_password_field)
            ),
            do: {:ok, [maybe_generate_token(record)]},
-           else: auth_failed(query)
+           else:
+             {:error,
+              AuthenticationFailed.exception(
+                query: query,
+                caused_by: %{
+                  module: __MODULE__,
+                  action: query.action,
+                  resource: query.resource,
+                  message: "Password is not valid"
+                }
+              )}
 
-      _, _ ->
+      query, [] ->
         strategy.hash_provider.simulate()
-        auth_failed(query)
+
+        {:error,
+         AuthenticationFailed.exception(
+           query: query,
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned no users"
+           }
+         )}
+
+      query, users when is_list(users) ->
+        strategy.hash_provider.simulate()
+
+        {:error,
+         AuthenticationFailed.exception(
+           query: query,
+           caused_by: %{
+             module: __MODULE__,
+             strategy: strategy,
+             action: :sign_in,
+             message: "Query returned too many users"
+           }
+         )}
     end)
   end
 
-  defp auth_failed(query), do: {:error, AuthenticationFailed.exception(query: query)}
-
   defp maybe_generate_token(record) do
     if AshAuthentication.Info.authentication_tokens_enabled?(record.__struct__) do
       {:ok, token, _claims} = Jwt.token_for_user(record)