[bug] Internal server error in logs since 3.13.3 release

kinetix commented

2024-11-30 21:19:23 +00:00

Your setup

From source

Extra details

Gentoo

Version

stable (3.13.3)

PostgreSQL version

15

What were you trying to do?

Nothing - just reviewing logs and noticed the errors, so I'll skip ahead to the log entries.

What did you expect to happen?

No response

What actually happened?

When speaking to Oneric in #akkoma about this, he recommended posting at least the log lines that I've pasted in here, and he thought there were two new bugs here.

16:18 < Oneric> There are also "could not figure out who owns the key" messages, but checking some of them they seem to originate from
deleted accounts
16:18 < Oneric> There’s also a "expected one but got two results" log re signing keys though
16:18 < Oneric> Thanks for bringing this up, this indeed appears to be (two) new bugs. Can you create an issue on akkoma.dev with at least
lines 97-100 of your larger excerpt attached (as well as any other info the template asks for) so this can be properly
tracked?

Logs

Nov 29 15:33:05 [mycrowd] request_id=GAyUdJ-XVkcGf5YAAD-D [error] Internal server error: %Ecto.MultipleResultsError{message: "expected at most one result but got 2 in query:\n\nfrom s0 in Pleroma.User.SigningKey,\n  where: s0.user_id == ^\"AjPEo08n9DW9ZrETz6\"\n"}
Nov 29 15:33:05 [mycrowd] [error] #PID<0.3036.0> running Pleroma.Web.Endpoint (connection #PID<0.3035.0>, stream id 1) terminated_Server: mycrowd.ca:80 (http)_Request: POST /inbox_** (exit) an exception was raised:_    ** (Ecto.MultipleResultsError) expected at most one result but got 2 in query:__from s0 in Pleroma.User.SigningKey,_  where: s0.user_id == ^"AjPEo08n9DW9ZrETz6"__        (ecto 3.10.3) lib/ecto/repo/queryable.ex:154: Ecto.Repo.Queryable.one/3_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/user/signing_key.ex:182: Pleroma.User.SigningKey.get_or_fetch_by_key_id/1_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/plugs/ensure_user_public_key_plug.ex:15: Pleroma.Web.Plugs.EnsureUserPublicKeyPlug.call/2_        (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.http_signature/2_        (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.activitypub/2_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/router.ex:5: Pleroma.Web.Router.__pipe_through21__/1_        (phoenix 1.7.14) lib/phoenix/router.ex:475: Phoenix.Router.__call__/5_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.plug_builder_call/2
Nov 29 15:33:10 [mycrowd] request_id=GAyUdbz4zYxVSYoAAAkH [error] Internal server error: %Ecto.MultipleResultsError{message: "expected at most one result but got 2 in query:\n\nfrom s0 in Pleroma.User.SigningKey,\n  where: s0.user_id == ^\"AcNO8UnRO1QM4EYK3c\"\n"}
Nov 29 15:33:10 [mycrowd] [error] #PID<0.3079.0> running Pleroma.Web.Endpoint (connection #PID<0.3078.0>, stream id 1) terminated_Server: mycrowd.ca:80 (http)_Request: POST /inbox_** (exit) an exception was raised:_    ** (Ecto.MultipleResultsError) expected at most one result but got 2 in query:__from s0 in Pleroma.User.SigningKey,_  where: s0.user_id == ^"AcNO8UnRO1QM4EYK3c"__        (ecto 3.10.3) lib/ecto/repo/queryable.ex:154: Ecto.Repo.Queryable.one/3_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/user/signing_key.ex:182: Pleroma.User.SigningKey.get_or_fetch_by_key_id/1_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/plugs/ensure_user_public_key_plug.ex:15: Pleroma.Web.Plugs.EnsureUserPublicKeyPlug.call/2_        (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.http_signature/2_        (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.activitypub/2_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/router.ex:5: Pleroma.Web.Router.__pipe_through21__/1_        (phoenix 1.7.14) lib/phoenix/router.ex:475: Phoenix.Router.__call__/5_        (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.plug_builder_call/2
Nov 29 15:33:15 [mycrowd] [error] Object rejected while fetching https://sfba.social/users/cynblogger/statuses/113568854301203915 {:transmogrifier, {:error, {:validate, {:error, #Ecto.Changeset<action: :insert, changes: %{type: "Create", context: "tag:hachyderm.io,2024-11-29:objectId=214983319:objectType=Conversation", cc: ["https://hachyderm.io/users/al3x", "https://sfba.social/users/cynblogger/followers"], to: ["https://www.w3.org/ns/activitystreams#Public"], actor: "https://sfba.social/users/cynblogger", object: "https://sfba.social/users/cynblogger/statuses/113568854301203915"}, errors: [object: {"The object to create already exists", []}], data: #Pleroma.Web.ActivityPub.ObjectValidators.CreateGenericValidator<>, valid?: false>}}}}

Severity

I can manage

Have you searched for this issue?

I have double-checked and have not found this issue mentioned anywhere.

### Your setup From source ### Extra details Gentoo ### Version stable (3.13.3) ### PostgreSQL version 15 ### What were you trying to do? Nothing - just reviewing logs and noticed the errors, so I'll skip ahead to the log entries. ### What did you expect to happen? _No response_ ### What actually happened? When speaking to Oneric in #akkoma about this, he recommended posting at least the log lines that I've pasted in here, and he thought there were two new bugs here. > 16:18 < Oneric> There are also "could not figure out who owns the key" messages, but checking some of them they seem to originate from > deleted accounts > 16:18 < Oneric> There’s also a "expected one but got two results" log re signing keys though > 16:18 < Oneric> Thanks for bringing this up, this indeed appears to be (two) new bugs. Can you create an issue on akkoma.dev with at least > lines 97-100 of your larger excerpt attached (as well as any other info the template asks for) so this can be properly > tracked? > ### Logs ```shell Nov 29 15:33:05 [mycrowd] request_id=GAyUdJ-XVkcGf5YAAD-D [error] Internal server error: %Ecto.MultipleResultsError{message: "expected at most one result but got 2 in query:\n\nfrom s0 in Pleroma.User.SigningKey,\n where: s0.user_id == ^\"AjPEo08n9DW9ZrETz6\"\n"} Nov 29 15:33:05 [mycrowd] [error] #PID<0.3036.0> running Pleroma.Web.Endpoint (connection #PID<0.3035.0>, stream id 1) terminated_Server: mycrowd.ca:80 (http)_Request: POST /inbox_** (exit) an exception was raised:_ ** (Ecto.MultipleResultsError) expected at most one result but got 2 in query:__from s0 in Pleroma.User.SigningKey,_ where: s0.user_id == ^"AjPEo08n9DW9ZrETz6"__ (ecto 3.10.3) lib/ecto/repo/queryable.ex:154: Ecto.Repo.Queryable.one/3_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/user/signing_key.ex:182: Pleroma.User.SigningKey.get_or_fetch_by_key_id/1_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/plugs/ensure_user_public_key_plug.ex:15: Pleroma.Web.Plugs.EnsureUserPublicKeyPlug.call/2_ (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.http_signature/2_ (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.activitypub/2_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/router.ex:5: Pleroma.Web.Router.__pipe_through21__/1_ (phoenix 1.7.14) lib/phoenix/router.ex:475: Phoenix.Router.__call__/5_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.plug_builder_call/2 Nov 29 15:33:10 [mycrowd] request_id=GAyUdbz4zYxVSYoAAAkH [error] Internal server error: %Ecto.MultipleResultsError{message: "expected at most one result but got 2 in query:\n\nfrom s0 in Pleroma.User.SigningKey,\n where: s0.user_id == ^\"AcNO8UnRO1QM4EYK3c\"\n"} Nov 29 15:33:10 [mycrowd] [error] #PID<0.3079.0> running Pleroma.Web.Endpoint (connection #PID<0.3078.0>, stream id 1) terminated_Server: mycrowd.ca:80 (http)_Request: POST /inbox_** (exit) an exception was raised:_ ** (Ecto.MultipleResultsError) expected at most one result but got 2 in query:__from s0 in Pleroma.User.SigningKey,_ where: s0.user_id == ^"AcNO8UnRO1QM4EYK3c"__ (ecto 3.10.3) lib/ecto/repo/queryable.ex:154: Ecto.Repo.Queryable.one/3_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/user/signing_key.ex:182: Pleroma.User.SigningKey.get_or_fetch_by_key_id/1_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/plugs/ensure_user_public_key_plug.ex:15: Pleroma.Web.Plugs.EnsureUserPublicKeyPlug.call/2_ (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.http_signature/2_ (pleroma 3.13.3-177-g34aa1694) Pleroma.Web.Router.activitypub/2_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/router.ex:5: Pleroma.Web.Router.__pipe_through21__/1_ (phoenix 1.7.14) lib/phoenix/router.ex:475: Phoenix.Router.__call__/5_ (pleroma 3.13.3-177-g34aa1694) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.plug_builder_call/2 Nov 29 15:33:15 [mycrowd] [error] Object rejected while fetching https://sfba.social/users/cynblogger/statuses/113568854301203915 {:transmogrifier, {:error, {:validate, {:error, #Ecto.Changeset<action: :insert, changes: %{type: "Create", context: "tag:hachyderm.io,2024-11-29:objectId=214983319:objectType=Conversation", cc: ["https://hachyderm.io/users/al3x", "https://sfba.social/users/cynblogger/followers"], to: ["https://www.w3.org/ns/activitystreams#Public"], actor: "https://sfba.social/users/cynblogger", object: "https://sfba.social/users/cynblogger/statuses/113568854301203915"}, errors: [object: {"The object to create already exists", []}], data: #Pleroma.Web.ActivityPub.ObjectValidators.CreateGenericValidator<>, valid?: false>}}}} ``` ### Severity I can manage ### Have you searched for this issue? - [x] I have double-checked and have not found this issue mentioned anywhere.

👍 3

kinetix added the

bug

label

2024-11-30 21:19:23 +00:00

poesty commented

2025-02-01 08:45:32 +00:00

I think this issue is more serious because its affecting the interconnection with Activity-Relay, where Akkoma instances can't follow or remove relay’s actors.
This bug is reproducible in 3.13.3, akkoma stable 2025.01 (3.14.0) and Hotfix 3.14.1. both my friend's and my instance have this issue.
Possible problematic sql commands: SELECT s0. “user_id”, s0. “public_key”, s0. “private_key”, s0. “key_id”, s0. “inserted_at”, s0. “updated_at”, s0. “user_id” FROM ” signing_keys” AS s0 WHERE (s0. ‘user_id’ = $1) corresponds to

{:ok, Repo.get_by(__MODULE__, user_id: user_id)}

Relevant link: https://meta.akkoma.dev/t/internal-server-error-ecto-multipleresultserror/810

I think this issue is more serious because its affecting the interconnection with Activity-Relay, where Akkoma instances can't follow or remove relay’s actors. This bug is reproducible in 3.13.3, akkoma stable 2025.01 (3.14.0) and Hotfix 3.14.1. both my friend's and my instance have this issue. Possible problematic sql commands: `SELECT s0. “user_id”, s0. “public_key”, s0. “private_key”, s0. “key_id”, s0. “inserted_at”, s0. “updated_at”, s0. “user_id” FROM ” signing_keys” AS s0 WHERE (s0. ‘user_id’ = $1)` corresponds to https://akkoma.dev/AkkomaGang/akkoma/src/commit/ad92e504d773e6bbeaee5a2ed47154a021ec66ed/lib/pleroma/user/signing_key.ex#L182 Relevant link: https://meta.akkoma.dev/t/internal-server-error-ecto-multipleresultserror/810

shadowjonathan commented

2025-02-09 11:48:53 +00:00

Contributor

I'm also encountering this error

shadowjonathan commented

2025-02-09 12:00:23 +00:00

Contributor

In my case this happened because a user seems to switch keys, which results in 2 results;

In my case this happened because a user seems to switch keys, which results in 2 results; ![image](/attachments/8355b175-7c1b-4413-b62e-93e52a66b8ff)

image.png

95 KiB

shadowjonathan commented

2025-02-09 12:18:06 +00:00

Contributor

this happens with gup.pe, where the key sent via HTTP signature is not (exactly) the same as the key in the database, and instead it creates two entries; one by fetching the entity (with #main-key), and one when it receives the key via http signature (without #main-key)

Edit: I've since created an issue highlighting this; https://github.com/immers-space/guppe/issues/113

this happens with gup.pe, where the key sent via HTTP signature is not (exactly) the same as the key in the database, and instead it creates two entries; one by fetching the entity (with `#main-key`), and one when it receives the key via http signature (without `#main-key`) Edit: I've since created an issue highlighting this; https://github.com/immers-space/guppe/issues/113

shadowjonathan commented

2025-02-09 12:27:13 +00:00

Contributor

I fixed this with the following patch;

diff --git a/lib/pleroma/user/signing_key.ex b/lib/pleroma/user/signing_key.ex
index 87149aa58..a5b0ce683 100644
--- a/lib/pleroma/user/signing_key.ex
+++ b/lib/pleroma/user/signing_key.ex
@@ -178,8 +178,8 @@ def get_or_fetch_by_key_id(key_id) do
       nil ->
         fetch_remote_key(key_id)

-      user_id ->
-        {:ok, Repo.get_by(__MODULE__, user_id: user_id)}
+      _user_id ->
+        {:ok, Repo.get_by(__MODULE__, key_id: key_id)}
     end
   end

Honestly, the expectation that there's only one user to signing key is not proper form here, since there's no UNIQUE index on signing_key for user -> key_id, and there's this following comment;

    # FOR THE FUTURE: We might want to make this a one-to-many relationship
    # it's entirely possible right now, but we don't have a use case for it
    has_one(:signing_key, SigningKey, foreign_key: :user_id)

I fixed this with the following patch; ```diff diff --git a/lib/pleroma/user/signing_key.ex b/lib/pleroma/user/signing_key.ex index 87149aa58..a5b0ce683 100644 --- a/lib/pleroma/user/signing_key.ex +++ b/lib/pleroma/user/signing_key.ex @@ -178,8 +178,8 @@ def get_or_fetch_by_key_id(key_id) do nil -> fetch_remote_key(key_id) - user_id -> - {:ok, Repo.get_by(__MODULE__, user_id: user_id)} + _user_id -> + {:ok, Repo.get_by(__MODULE__, key_id: key_id)} end end ``` Honestly, the expectation that there's only one user to signing key is not proper form here, since there's no `UNIQUE` index on `signing_key` for `user -> key_id`, and there's [this following comment](https://akkoma.dev/AkkomaGang/akkoma/src/commit/ad92e504d773e6bbeaee5a2ed47154a021ec66ed/lib/pleroma/user.ex#L224-L226); ```elixir # FOR THE FUTURE: We might want to make this a one-to-many relationship # it's entirely possible right now, but we don't have a use case for it has_one(:signing_key, SigningKey, foreign_key: :user_id) ```

👍 2

shadowjonathan commented

2025-03-01 13:30:27 +00:00

Contributor

It seems this was fixed with cc5c1bb10c and surrounding commits?

Unsure if there was also a PR attached, but that commit should fix this issue.

It seems this was fixed with cc5c1bb10c99fbd90ca396caa01115be973fb27d and surrounding commits? Unsure if there was also a PR attached, but that commit should fix this issue.

poesty commented

2025-03-01 13:38:45 +00:00

[error] Object rejected while fetching https://[REDACTED]/actor {:strict_id, {:error, "https://[REDACTED]/actor#main-key"}}
[error] Failed to acquire key from signature: https://[REDACTED]/actor {:error, "Could not fetch key"}
[error] Failed to extract actor_id from signature: signing key https://[REDACTED]/actor not known

Federation with Activity-Relay still seems broken

``` [error] Object rejected while fetching https://[REDACTED]/actor {:strict_id, {:error, "https://[REDACTED]/actor#main-key"}} [error] Failed to acquire key from signature: https://[REDACTED]/actor {:error, "Could not fetch key"} [error] Failed to extract actor_id from signature: signing key https://[REDACTED]/actor not known ``` Federation with Activity-Relay still seems broken

Oneric commented

2025-03-01 20:06:41 +00:00

Owner

This should be fixed now with 3.15.0

Oneric referenced this issue

2025-03-01 20:07:16 +00:00

meta: closeable issues #758

grassblock commented

2025-03-02 07:49:00 +00:00

@Oneric wrote in #858 (comment):

This should be fixed now with 3.15.0

I tried with the 3.15.1 but it's not fixed for relays:

07:41:21.311 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to acquire key from signature: https://relay/actor {:error, "Could not fetch key"}

07:41:21.314 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to extract actor_id from signature: signing key https://relay/actor not known

07:41:21.373 request_id=GCjsfdZJCFDR03QAATGE [error] Object rejected while fetching https://relay/actor {:strict_id, {:error, "https://relay/actor#main-key"}}

07:41:21.373 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to acquire key from signature: https://relay/actor {:error, "Could not fetch key"}

07:41:21.375 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to extract actor_id from signature: signing key https://relay/actor not known

I searched the instance list provided by the relay and I couldn't find my instance.
and the relays doesn't display "Followed back" as ✅ in admin-fe.

@Oneric wrote in https://akkoma.dev/AkkomaGang/akkoma/issues/858#issuecomment-13745: > This should be fixed now with 3.15.0 I tried with the 3.15.1 but it's not fixed for relays: ``` 07:41:21.311 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to acquire key from signature: https://relay/actor {:error, "Could not fetch key"} 07:41:21.314 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to extract actor_id from signature: signing key https://relay/actor not known 07:41:21.373 request_id=GCjsfdZJCFDR03QAATGE [error] Object rejected while fetching https://relay/actor {:strict_id, {:error, "https://relay/actor#main-key"}} 07:41:21.373 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to acquire key from signature: https://relay/actor {:error, "Could not fetch key"} 07:41:21.375 request_id=GCjsfdZJCFDR03QAATGE [error] Failed to extract actor_id from signature: signing key https://relay/actor not known ``` I searched the instance list provided by the relay and I couldn't find my instance. and the relays doesn't display "Followed back" as ✅ in admin-fe.

Oneric commented

2025-03-02 15:27:45 +00:00

Owner

If you don't see a "500 internal server error" and "MultipleResults" exception in your logs, the original bug is fixed.
The logs you’re showing are something completely different; please do not hijack existing issues with unrelated problems, but create a new issue.

Regardless: your logs indicate that the relay actor is not using the same key id in it’s actor representation and its signatures. Specifically the ID used in its signatures is it’s actor rather than key ID. This is a bug of the relay; Bookwyrm had a similar bug a while ago which broke its federation with e.g. GTS.
The relay URls you’re showing here don't look like akkoma relay actor URLs so this is not our bug, contact whoever develops the relay. (And if you want to write anything further about this, create a new issue)

If you don't see a "500 internal server error" and "MultipleResults" exception in your logs, the original bug **is** fixed. The logs you’re showing are something completely different; please do not hijack existing issues with unrelated problems, but create a new issue. Regardless: your logs indicate that the relay actor is not using the same key id in it’s actor representation and its signatures. Specifically the ID used in its signatures is it’s actor rather than key ID. This is a bug _of the relay_; Bookwyrm had a similar bug a while ago which broke its federation with e.g. GTS. The relay URls you’re showing here don't look like akkoma relay actor URLs so this is not our bug, contact whoever develops the relay. *(And if you want to write anything further about this, create a new issue)*

👍 1