Log failed-signature retry rejections

lib/pleroma/workers/signature_retry_worker.ex

@@ -10,6 +10,8 @@ defmodule Pleroma.Workers.SignatureRetryWorker do
   alias Pleroma.Web.Federator
   alias Pleroma.Web.Plugs.MappedSignatureToIdentityPlug
 
+  require Logger
+
   use Oban.Worker, queue: :federator_incoming, max_attempts: 5, unique: [period: :infinity]
 
   @impl true
@@ -25,37 +27,55 @@ defmodule Pleroma.Workers.SignatureRetryWorker do
       })
       when is_binary(method) and is_map(params) and is_list(req_headers) and
              is_binary(request_path) and is_binary(query_string) do
-    with {:ok, req_headers} <- normalize_req_headers(req_headers),
+    case normalize_req_headers(req_headers) do
-         conn_data = %Plug.Conn{
+      {:ok, req_headers} ->
-           assigns: %{valid_signature: true},
+        conn_data = %Plug.Conn{
-           method: method,
+          assigns: %{valid_signature: true},
-           params: params,
+          method: method,
-           req_headers: req_headers,
+          params: params,
-           request_path: request_path,
+          req_headers: req_headers,
-           query_string: query_string
+          request_path: request_path,
-         },
+          query_string: query_string
-         actor_id = Utils.get_ap_id(params["actor"]),
+        }
-         {:signature_actor, {:ok, signature_actor_id}} <-
-           {:signature_actor, signature_actor_id(conn_data)},
-         {:same_actor, true} <- {:same_actor, signature_actor_id == actor_id},
-         {:ok, %User{}} <- User.get_or_fetch_by_ap_id(actor_id),
-         {:ok, _public_key} <- Signature.refetch_public_key(conn_data),
-         {:signature, true} <- {:signature, validate_signature(conn_data)},
-         {:same_actor, true} <- {:same_actor, validate_same_actor(conn_data)},
-         {:ok, res} <- Federator.perform(:incoming_ap_doc, params) do
-      unless Instances.reachable?(params["actor"]) do
-        domain = URI.parse(params["actor"]).host
-        Oban.insert(Pleroma.Workers.ReachabilityWorker.new(%{"domain" => domain}))
-      end
 
-      {:ok, res}
+        signature_actor_result = signature_actor_id(conn_data)
-    else
+
-      e -> process_errors(e)
+        with actor_id = Utils.get_ap_id(params["actor"]),
+             {:signature_actor, {:ok, signature_actor_id}} <-
+               {:signature_actor, signature_actor_result},
+             {:same_actor, true} <- {:same_actor, signature_actor_id == actor_id},
+             {:ok, %User{}} <- User.get_or_fetch_by_ap_id(actor_id),
+             {:ok, _public_key} <- Signature.refetch_public_key(conn_data),
+             {:signature, true} <- {:signature, validate_signature(conn_data)},
+             {:same_actor, true} <- {:same_actor, validate_same_actor(conn_data)},
+             {:ok, res} <- Federator.perform(:incoming_ap_doc, params) do
+          unless Instances.reachable?(params["actor"]) do
+            domain = URI.parse(params["actor"]).host
+            Oban.insert(Pleroma.Workers.ReachabilityWorker.new(%{"domain" => domain}))
+          end
+
+          {:ok, res}
+        else
+          e -> process_errors(e, retry_log_context(params, request_path, signature_actor_result))
+        end
+
+      e ->
+        process_errors(e, retry_log_context(params, request_path, nil))
     end
   end
 
-  def perform(%Job{args: %{"op" => "incoming_failed_signature_ap_doc"}}) do
+  def perform(%Job{args: %{"op" => "incoming_failed_signature_ap_doc"} = args}) do
-    process_errors(:missing_signature_retry_metadata)
+    process_errors(
+      :missing_signature_retry_metadata,
+      retry_log_context(Map.get(args, "params"), Map.get(args, "request_path"), nil)
+    )
+  end
+
+  def perform(%Job{args: args}) when is_map(args) do
+    process_errors(
+      :missing_signature_retry_metadata,
+      retry_log_context(Map.get(args, "params"), Map.get(args, "request_path"), nil)
+    )
   end
 
   def perform(%Job{}), do: process_errors(:missing_signature_retry_metadata)
@@ -109,36 +129,126 @@ defmodule Pleroma.Workers.SignatureRetryWorker do
     _, _ -> {:error, :invalid_signature}
   end
 
-  defp process_errors({:error, {:error, _} = error}), do: process_errors(error)
+  defp process_errors(errors, context \\ %{})
 
-  defp process_errors(errors) do
+  defp process_errors({:error, {:error, _} = error}, context), do: process_errors(error, context)
-    case errors do
+
-      # User fetch failures
+  defp process_errors(errors, context) do
-      {:error, :not_found} = reason -> {:cancel, reason}
+    result =
-      {:error, :forbidden} = reason -> {:cancel, reason}
+      case errors do
-      # Inactive user
+        # User fetch failures
-      {:error, {:user_active, false} = reason} -> {:cancel, reason}
+        {:error, :not_found} = reason ->
-      # Validator will error and return a changeset error
+          {:cancel, reason}
-      # e.g., duplicate activities or if the object was deleted
+
-      {:error, {:validate, {:error, _changeset} = reason}} -> {:cancel, reason}
+        {:error, :forbidden} = reason ->
-      # Duplicate detection during Normalization
+          {:cancel, reason}
-      {:error, :already_present} -> {:cancel, :already_present}
+
-      # MRFs will return a reject
+        # Inactive user
-      {:error, {:reject, _} = reason} -> {:cancel, reason}
+        {:error, {:user_active, false} = reason} ->
-      # HTTP Sigs
+          {:cancel, reason}
-      {:signature_actor, {:error, _}} -> {:cancel, :invalid_signature}
+
-      {:signature, false} -> {:cancel, :invalid_signature}
+        # Validator will error and return a changeset error
-      {:same_actor, false} -> {:cancel, :actor_signature_mismatch}
+        # e.g., duplicate activities or if the object was deleted
-      # Origin / URL validation failed somewhere possibly due to spoofing
+        {:error, {:validate, {:error, _changeset} = reason}} ->
-      {:error, :origin_containment_failed} -> {:cancel, :origin_containment_failed}
+          {:cancel, reason}
-      # Unclear if this can be reached
+
-      {:error, {:side_effects, {:error, :no_object_actor}} = reason} -> {:cancel, reason}
+        # Duplicate detection during Normalization
-      # Fail closed if the retry cannot reconstruct the original request.
+        {:error, :already_present} ->
-      :missing_signature_retry_metadata -> {:cancel, :missing_signature_retry_metadata}
+          {:cancel, :already_present}
-      {:error, :invalid_signature_retry_metadata} -> {:cancel, :invalid_signature_retry_metadata}
+
-      # Catchall
+        # MRFs will return a reject
-      {:error, _} = e -> e
+        {:error, {:reject, _} = reason} ->
-      e -> {:error, e}
+          {:cancel, reason}
-    end
+
+        # HTTP Sigs
+        {:signature_actor, {:error, _}} ->
+          {:cancel, :invalid_signature}
+
+        {:signature, false} ->
+          {:cancel, :invalid_signature}
+
+        {:same_actor, false} ->
+          {:cancel, :actor_signature_mismatch}
+
+        # Origin / URL validation failed somewhere possibly due to spoofing
+        {:error, :origin_containment_failed} ->
+          {:cancel, :origin_containment_failed}
+
+        # Unclear if this can be reached
+        {:error, {:side_effects, {:error, :no_object_actor}} = reason} ->
+          {:cancel, reason}
+
+        # Fail closed if the retry cannot reconstruct the original request.
+        :missing_signature_retry_metadata ->
+          {:cancel, :missing_signature_retry_metadata}
+
+        {:error, :invalid_signature_retry_metadata} ->
+          {:cancel, :invalid_signature_retry_metadata}
+
+        # Catchall
+        {:error, _} = e ->
+          e
+
+        e ->
+          {:error, e}
+      end
+
+    log_signature_retry_rejection(result, context)
+    result
   end
+
+  defp retry_log_context(params, request_path, signature_actor_result) when is_map(params) do
+    signature_actor =
+      case signature_actor_result do
+        {:ok, actor} when is_binary(actor) -> actor
+        actor when is_binary(actor) -> actor
+        _ -> nil
+      end
+
+    %{
+      activity_id: params["id"],
+      payload_actor: Utils.get_ap_id(params["actor"]),
+      request_path: request_path,
+      signature_actor: signature_actor,
+      type: params["type"]
+    }
+  end
+
+  defp retry_log_context(_params, request_path, signature_actor_result) do
+    signature_actor =
+      case signature_actor_result do
+        {:ok, actor} when is_binary(actor) -> actor
+        actor when is_binary(actor) -> actor
+        _ -> nil
+      end
+
+    %{
+      activity_id: nil,
+      payload_actor: nil,
+      request_path: request_path,
+      signature_actor: signature_actor,
+      type: nil
+    }
+  end
+
+  defp log_signature_retry_rejection({:cancel, reason}, context)
+       when reason in [
+              :actor_signature_mismatch,
+              :invalid_signature,
+              :invalid_signature_retry_metadata,
+              :missing_signature_retry_metadata,
+              :origin_containment_failed
+            ] do
+    Logger.warning(
+      "Failed-signature inbox retry rejected " <>
+        "reason=#{inspect(reason)} " <>
+        "payload_actor=#{inspect(context[:payload_actor])} " <>
+        "signature_actor=#{inspect(context[:signature_actor])} " <>
+        "activity_id=#{inspect(context[:activity_id])} " <>
+        "type=#{inspect(context[:type])} " <>
+        "request_path=#{inspect(context[:request_path])}"
+    )
+  end
+
+  defp log_signature_retry_rejection(_result, _context), do: :ok
 end

test/pleroma/workers/signature_retry_worker_test.exs

@@ -6,8 +6,11 @@ defmodule Pleroma.Workers.SignatureRetryWorkerTest do
   use Pleroma.DataCase, async: false
   use Oban.Testing, repo: Pleroma.Repo
 
+  import ExUnit.CaptureLog
   import Pleroma.Factory
 
+  @moduletag capture_log: true
+
   alias Pleroma.Activity
   alias Pleroma.Object
   alias Pleroma.Signature
@@ -73,7 +76,9 @@ defmodule Pleroma.Workers.SignatureRetryWorkerTest do
   defp assert_mismatched_signature_cancelled(params, signer) do
     assert {:ok, oban_job} = enqueue_failed_signature(params, signer)
 
-    assert {:cancel, :actor_signature_mismatch} = SignatureRetryWorker.perform(oban_job)
+    capture_log([level: :warning], fn ->
+      assert {:cancel, :actor_signature_mismatch} = SignatureRetryWorker.perform(oban_job)
+    end)
   end
 
   test "Federator preserves request metadata for failed-signature retry jobs" do
@@ -108,25 +113,54 @@ defmodule Pleroma.Workers.SignatureRetryWorkerTest do
   test "cancels retry jobs without request metadata" do
     params = insert(:note_activity).data
 
-    assert {:cancel, :missing_signature_retry_metadata} =
+    log =
-             SignatureRetryWorker.perform(%Oban.Job{
+      capture_log([level: :warning], fn ->
-               args: %{"op" => "incoming_failed_signature_ap_doc", "params" => params}
+        assert {:cancel, :missing_signature_retry_metadata} =
-             })
+                 SignatureRetryWorker.perform(%Oban.Job{
+                   args: %{"op" => "incoming_failed_signature_ap_doc", "params" => params}
+                 })
+      end)
+
+    assert log =~ "Failed-signature inbox retry rejected"
+    assert log =~ "reason=:missing_signature_retry_metadata"
+    assert log =~ "payload_actor=#{inspect(params["actor"])}"
+    assert log =~ "activity_id=#{inspect(params["id"])}"
+    assert log =~ "type=#{inspect(params["type"])}"
+    assert log =~ "request_path=nil"
   end
 
   test "cancels retry jobs with malformed serialized request headers" do
     params = insert(:note_activity).data
 
-    assert {:cancel, :invalid_signature_retry_metadata} =
+    log =
-             SignatureRetryWorker.perform(failed_signature_job(params, [["signature"]]))
+      capture_log([level: :warning], fn ->
+        assert {:cancel, :invalid_signature_retry_metadata} =
+                 SignatureRetryWorker.perform(failed_signature_job(params, [["signature"]]))
+      end)
+
+    assert log =~ "Failed-signature inbox retry rejected"
+    assert log =~ "reason=:invalid_signature_retry_metadata"
+    assert log =~ "signature_actor=nil"
+    assert log =~ "request_path=\"/inbox\""
   end
 
   test "cancels retry jobs without a signature header" do
     alice = insert(:user, local: false, ap_id: "https://one.com/users/alice")
     params = insert(:note_activity, user: alice).data
 
-    assert {:cancel, :invalid_signature} =
+    log =
-             SignatureRetryWorker.perform(failed_signature_job(params, [{"host", "local.test"}]))
+      capture_log([level: :warning], fn ->
+        assert {:cancel, :invalid_signature} =
+                 SignatureRetryWorker.perform(
+                   failed_signature_job(params, [{"host", "local.test"}])
+                 )
+      end)
+
+    assert log =~ "Failed-signature inbox retry rejected"
+    assert log =~ "reason=:invalid_signature"
+    assert log =~ "payload_actor=#{inspect(params["actor"])}"
+    assert log =~ "signature_actor=nil"
+    assert log =~ "request_path=\"/inbox\""
   end
 
   test "cancels missing signature before fetching an unavailable payload actor" do
@@ -194,7 +228,20 @@ defmodule Pleroma.Workers.SignatureRetryWorkerTest do
     stub_actor_fetch(alice)
 
     assert {:ok, oban_job} = enqueue_failed_signature(create, alice)
-    assert {:cancel, :invalid_signature} = SignatureRetryWorker.perform(oban_job)
+
+    log =
+      capture_log([level: :warning], fn ->
+        assert {:cancel, :invalid_signature} = SignatureRetryWorker.perform(oban_job)
+      end)
+
+    assert log =~ "Failed-signature inbox retry rejected"
+    assert log =~ "reason=:invalid_signature"
+    assert log =~ "payload_actor=\"https://one.com/users/alice\""
+    assert log =~ "signature_actor=\"https://one.com/users/alice\""
+    assert log =~ "activity_id=\"https://one.com/activities/invalid-signature-create\""
+    assert log =~ "type=\"Create\""
+    assert log =~ "request_path=\"/inbox\""
+
     refute Activity.get_by_ap_id(create["id"])
   end
 
@@ -352,6 +399,39 @@ defmodule Pleroma.Workers.SignatureRetryWorkerTest do
     assert_mismatched_signature_cancelled(create, alice)
   end
 
+  test "logs signature actor mismatch retry rejections" do
+    alice = insert(:user, local: false, ap_id: "https://one.com/users/alice")
+    bob = insert(:user, local: false, ap_id: "https://two.com/users/bob")
+
+    create = %{
+      "type" => "Create",
+      "actor" => bob.ap_id,
+      "id" => "https://two.com/activities/logged-forged-create",
+      "to" => ["https://www.w3.org/ns/activitystreams#Public"],
+      "cc" => [],
+      "object" => %{
+        "type" => "Note",
+        "id" => "https://two.com/objects/logged-forged-note",
+        "actor" => bob.ap_id,
+        "attributedTo" => bob.ap_id,
+        "content" => "forged post",
+        "published" => "2024-07-25T13:33:31Z",
+        "to" => ["https://www.w3.org/ns/activitystreams#Public"],
+        "cc" => []
+      }
+    }
+
+    log = assert_mismatched_signature_cancelled(create, alice)
+
+    assert log =~ "Failed-signature inbox retry rejected"
+    assert log =~ "reason=:actor_signature_mismatch"
+    assert log =~ "payload_actor=\"https://two.com/users/bob\""
+    assert log =~ "signature_actor=\"https://one.com/users/alice\""
+    assert log =~ "activity_id=\"https://two.com/activities/logged-forged-create\""
+    assert log =~ "type=\"Create\""
+    assert log =~ "request_path=\"/inbox\""
+  end
+
   test "cancels signature actor mismatch before actually creating a forged post" do
     alice = insert(:user, local: false, ap_id: "https://one.com/users/alice")
     bob = insert(:user, local: false, ap_id: "https://two.com/users/bob")