From 49920c24982ad838db07f5b847bbc17c95455b4b Mon Sep 17 00:00:00 2001 From: Oneric Date: Sat, 14 Dec 2024 21:40:21 +0100 Subject: [PATCH] Add patch to avoid :not_found user log spam --- patches/series | 3 +- ...ator-explain-refetch-reason-in-comme.patch | 26 ---- ...dator-limit-refetch-rate-to-1-per-5s.patch | 42 ++++++ ..._Don-t-spam-logs-about-deleted-users.patch | 141 ++++++++++++++++++ 4 files changed, 185 insertions(+), 27 deletions(-) delete mode 100644 patches/wip_03_add_remove_validator-explain-refetch-reason-in-comme.patch create mode 100644 patches/wip_03_add_remove_validator-limit-refetch-rate-to-1-per-5s.patch create mode 100644 patches/wip_23_Don-t-spam-logs-about-deleted-users.patch diff --git a/patches/series b/patches/series index 8be76c1..7ecc0fe 100644 --- a/patches/series +++ b/patches/series @@ -29,7 +29,7 @@ up-2b1a252cc78dbb3ff8a34a8365b8c049c0b531fb_truncate-remote-user-fields.patch # testing various perf tweaks wip_01_Purge-obsolete-ap_enabled-indicator.patch wip_02_Drop-ap_enabled-indicator-from-atom-feeds.patch -wip_03_add_remove_validator-explain-refetch-reason-in-comme.patch +wip_03_add_remove_validator-limit-refetch-rate-to-1-per-5s.patch wip_04_federator-don-t-fetch-the-user-for-no-reason.patch wip_05_validators-add_remove-don-t-crash-on-failure-to-reso.patch wip_06_workers-make-custom-filtering-ahead-of-enqueue-possi.patch @@ -49,3 +49,4 @@ wip_19_Error-out-earlier-on-missing-mandatory-reference.patch wip_20_federation-incoming-improve-link_resolve-retry-decis.patch wip_21_nodeinfo-lower-log-level-of-regular-actions-to-debug.patch wip_22_rich_media-lower-log-level-of-update.patch +wip_23_Don-t-spam-logs-about-deleted-users.patch diff --git a/patches/wip_03_add_remove_validator-explain-refetch-reason-in-comme.patch b/patches/wip_03_add_remove_validator-explain-refetch-reason-in-comme.patch deleted file mode 100644 index 9d0d1f3..0000000 --- a/patches/wip_03_add_remove_validator-explain-refetch-reason-in-comme.patch +++ /dev/null @@ -1,26 +0,0 @@ -From bd3fbe43b1773b22a148f4073485e48bc3b4f055 Mon Sep 17 00:00:00 2001 -From: Oneric -Date: Fri, 13 Dec 2024 01:09:35 +0100 -Subject: [PATCH 03/22] add_remove_validator: explain refetch reason in comment - ---- - .../web/activity_pub/object_validators/add_remove_validator.ex | 3 ++- - 1 file changed, 2 insertions(+), 1 deletion(-) - -diff --git a/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex b/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex -index b2fa35831..a960e99b1 100644 ---- a/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex -+++ b/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex -@@ -73,7 +73,8 @@ defp maybe_refetch_user(%User{featured_address: address} = user) when is_binary( - end - - defp maybe_refetch_user(%User{ap_id: ap_id}) do -- # Maybe it could use User.get_or_fetch_by_ap_id to avoid refreshing too often -+ # If the user didn't expose a featured collection before, -+ # recheck now so we can verify perms for add/remove - User.fetch_by_ap_id(ap_id) - end - end --- -2.39.5 - diff --git a/patches/wip_03_add_remove_validator-limit-refetch-rate-to-1-per-5s.patch b/patches/wip_03_add_remove_validator-limit-refetch-rate-to-1-per-5s.patch new file mode 100644 index 0000000..e3bf55e --- /dev/null +++ b/patches/wip_03_add_remove_validator-limit-refetch-rate-to-1-per-5s.patch @@ -0,0 +1,42 @@ +From b762c76dd7ecbc10b6ffef32b897f3800d0313cc Mon Sep 17 00:00:00 2001 +From: Oneric +Date: Fri, 13 Dec 2024 01:09:35 +0100 +Subject: [PATCH] add_remove_validator: limit refetch rate to 1 per 5s + +This matches the maximum_age used when processing Move activities +--- + .../activity_pub/object_validators/add_remove_validator.ex | 6 ++++-- + .../transmogrifier/add_remove_handling_test.exs | 1 + + 2 files changed, 5 insertions(+), 2 deletions(-) + +diff --git a/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex b/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex +index b2fa35831..c13f7d442 100644 +--- a/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex ++++ b/lib/pleroma/web/activity_pub/object_validators/add_remove_validator.ex +@@ -73,7 +73,9 @@ defp maybe_refetch_user(%User{featured_address: address} = user) when is_binary( + end + + defp maybe_refetch_user(%User{ap_id: ap_id}) do +- # Maybe it could use User.get_or_fetch_by_ap_id to avoid refreshing too often +- User.fetch_by_ap_id(ap_id) ++ # If the user didn't expose a featured collection before, ++ # recheck now so we can verify perms for add/remove. ++ # But wait at least 5s to avoid rapid refetches in edge cases ++ User.get_or_fetch_by_ap_id(ap_id, maximum_age: 5) + end + end +diff --git a/test/pleroma/web/activity_pub/transmogrifier/add_remove_handling_test.exs b/test/pleroma/web/activity_pub/transmogrifier/add_remove_handling_test.exs +index c2b5f2cc8..f95d298e0 100644 +--- a/test/pleroma/web/activity_pub/transmogrifier/add_remove_handling_test.exs ++++ b/test/pleroma/web/activity_pub/transmogrifier/add_remove_handling_test.exs +@@ -102,6 +102,7 @@ test "Add/Remove activities for remote users without featured address" do + user = + user + |> Ecto.Changeset.change(featured_address: nil) ++ |> Ecto.Changeset.change(last_refreshed_at: ~N[2013-03-14 11:50:00.000000]) + |> Repo.update!() + + %{host: host} = URI.parse(user.ap_id) +-- +2.39.5 + diff --git a/patches/wip_23_Don-t-spam-logs-about-deleted-users.patch b/patches/wip_23_Don-t-spam-logs-about-deleted-users.patch new file mode 100644 index 0000000..9e20773 --- /dev/null +++ b/patches/wip_23_Don-t-spam-logs-about-deleted-users.patch @@ -0,0 +1,141 @@ +From f0a4ae22634140fe4e0dff7bbfe71356a18c8f2b Mon Sep 17 00:00:00 2001 +From: Oneric +Date: Sat, 14 Dec 2024 21:03:16 +0100 +Subject: [PATCH] Don't spam logs about deleted users +MIME-Version: 1.0 +Content-Type: text/plain; charset=UTF-8 +Content-Transfer-Encoding: 8bit + +User.get_or_fetch_by_(apid|nickname) are the only external users of fetch_and_prepare_user_from_ap_id, +thus there’s no point in duplicating logging, expecially not at error level. +Currently (duplicated) _not_found errors for users make up the bulk of my logs +and are created almost every second. Deleted users are a common occurence and not +worth logging outside of debug +--- + lib/pleroma/user.ex | 10 +++++++++- + lib/pleroma/web/activity_pub/activity_pub.ex | 11 ++++------- + .../activity_pub/mrf/anti_link_spam_policy_test.exs | 8 ++++---- + test/pleroma/web/activity_pub/relay_test.exs | 4 ++-- + .../web/twitter_api/remote_follow_controller_test.exs | 2 +- + 5 files changed, 20 insertions(+), 15 deletions(-) + +diff --git a/lib/pleroma/user.ex b/lib/pleroma/user.ex +index 2e09a89b6..2f4ac1b72 100644 +--- a/lib/pleroma/user.ex ++++ b/lib/pleroma/user.ex +@@ -2003,8 +2003,16 @@ def get_or_fetch_by_ap_id(ap_id, options \\ []) do + Logger.debug("Rejected to fetch user due to MRF: #{ap_id}") + {:error, {:reject, :mrf}} + +- e -> ++ {_, {:error, :not_found}} -> ++ Logger.debug("User doesn't exist (anymore): #{ap_id}") ++ {:error, :not_found} ++ ++ {_, {:error, e}} -> + Logger.error("Could not fetch user #{ap_id}, #{inspect(e)}") ++ {:error, e} ++ ++ e -> ++ Logger.error("Unexpected error condition while fetching user #{ap_id}, #{inspect(e)}") + {:error, :not_found} + end + end +diff --git a/lib/pleroma/web/activity_pub/activity_pub.ex b/lib/pleroma/web/activity_pub/activity_pub.ex +index 494a27421..224767b80 100644 +--- a/lib/pleroma/web/activity_pub/activity_pub.ex ++++ b/lib/pleroma/web/activity_pub/activity_pub.ex +@@ -1750,19 +1750,16 @@ defp fetch_and_prepare_user_from_ap_id(ap_id, additional) do + else + # If this has been deleted, only log a debug and not an error + {:error, {"Object has been deleted", _, _} = e} -> +- Logger.debug("Could not decode user at fetch #{ap_id}, #{inspect(e)}") +- {:error, e} ++ Logger.debug("User was explicitly deleted #{ap_id}, #{inspect(e)}") ++ {:error, :not_found} + +- {:reject, reason} = e -> +- Logger.debug("Rejected user #{ap_id}: #{inspect(reason)}") ++ {:reject, _reason} = e -> + {:error, e} + + {:valid, reason} -> +- Logger.debug("Data is not a valid user #{ap_id}: #{inspect(reason)}") +- {:error, "Not a user"} ++ {:error, {:validate, reason}} + + {:error, e} -> +- Logger.error("Could not decode user at fetch #{ap_id}, #{inspect(e)}") + {:error, e} + end + end +diff --git a/test/pleroma/web/activity_pub/mrf/anti_link_spam_policy_test.exs b/test/pleroma/web/activity_pub/mrf/anti_link_spam_policy_test.exs +index 6182e9717..291108da9 100644 +--- a/test/pleroma/web/activity_pub/mrf/anti_link_spam_policy_test.exs ++++ b/test/pleroma/web/activity_pub/mrf/anti_link_spam_policy_test.exs +@@ -241,11 +241,11 @@ test "it rejects posts without links" do + + assert capture_log(fn -> + {:reject, _} = AntiLinkSpamPolicy.filter(message) +- end) =~ "[error] Could not decode user at fetch http://invalid.actor" ++ end) =~ "[error] Could not fetch user http://invalid.actor," + + assert capture_log(fn -> + {:reject, _} = AntiLinkSpamPolicy.filter(update_message) +- end) =~ "[error] Could not decode user at fetch http://invalid.actor" ++ end) =~ "[error] Could not fetch user http://invalid.actor," + end + + test "it rejects posts with links" do +@@ -259,11 +259,11 @@ test "it rejects posts with links" do + + assert capture_log(fn -> + {:reject, _} = AntiLinkSpamPolicy.filter(message) +- end) =~ "[error] Could not decode user at fetch http://invalid.actor" ++ end) =~ "[error] Could not fetch user http://invalid.actor," + + assert capture_log(fn -> + {:reject, _} = AntiLinkSpamPolicy.filter(update_message) +- end) =~ "[error] Could not decode user at fetch http://invalid.actor" ++ end) =~ "[error] Could not fetch user http://invalid.actor," + end + end + +diff --git a/test/pleroma/web/activity_pub/relay_test.exs b/test/pleroma/web/activity_pub/relay_test.exs +index 99cc2071e..b1c927b49 100644 +--- a/test/pleroma/web/activity_pub/relay_test.exs ++++ b/test/pleroma/web/activity_pub/relay_test.exs +@@ -29,7 +29,7 @@ test "relay actor is invisible" do + test "returns errors when user not found" do + assert capture_log(fn -> + {:error, _} = Relay.follow("test-ap-id") +- end) =~ "Could not decode user at fetch" ++ end) =~ "Could not fetch user test-ap-id," + end + + test "returns activity" do +@@ -48,7 +48,7 @@ test "returns activity" do + test "returns errors when user not found" do + assert capture_log(fn -> + {:error, _} = Relay.unfollow("test-ap-id") +- end) =~ "Could not decode user at fetch" ++ end) =~ "Could not fetch user test-ap-id," + end + + test "returns activity" do +diff --git a/test/pleroma/web/twitter_api/remote_follow_controller_test.exs b/test/pleroma/web/twitter_api/remote_follow_controller_test.exs +index 5a94e4396..66e19b5ef 100644 +--- a/test/pleroma/web/twitter_api/remote_follow_controller_test.exs ++++ b/test/pleroma/web/twitter_api/remote_follow_controller_test.exs +@@ -132,7 +132,7 @@ test "show follow page with error when user can not be fetched by `acct` link", + |> html_response(200) + + assert response =~ "Error fetching user" +- end) =~ ":not_found" ++ end) =~ "User doesn't exist (anymore): https://mastodon.social/users/not_found" + end + end + +-- +2.39.5 +