Add patch to avoid :not_found user log spam

This commit is contained in:
Oneric 2024-12-14 21:40:21 +01:00
parent aa01097960
commit 49920c2498
4 changed files with 185 additions and 27 deletions

View file

@ -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

View file

@ -1,26 +0,0 @@
From bd3fbe43b1773b22a148f4073485e48bc3b4f055 Mon Sep 17 00:00:00 2001
From: Oneric <oneric@oneric.stub>
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

View file

@ -0,0 +1,42 @@
From b762c76dd7ecbc10b6ffef32b897f3800d0313cc Mon Sep 17 00:00:00 2001
From: Oneric <oneric@oneric.stub>
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

View file

@ -0,0 +1,141 @@
From f0a4ae22634140fe4e0dff7bbfe71356a18c8f2b Mon Sep 17 00:00:00 2001
From: Oneric <oneric@oneric.stub>
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 theres 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