Signature verification fails, but only with events from matrix.org

Elara6331 commented 1 year ago

Background information

Dendrite version or git SHA: 0.13.2+57ddbe0.57ddbe0
SQLite3 or Postgres?: Postgres
Running in Docker?: Yes
go version: N/A (go doesn't exist in docker container)
Client used (if applicable): N/A

Description

What is the problem: Requests specifically from matrix.org fail signature verification. Requests from other servers work correctly.
Who is affected: Clients on my server
How is this bug manifesting: Users on matrix.org can see messages from local users but local users cannot see messages from matrix.org. This doesn't happen with any homeserver other than matrix.org. Occasional logs containing Bad signature from \"matrix.org\" with ID \"ed25519:a_RXGa\". This is not happening with another dendrite homeserver I run, which is using the same version of dendrite.
When did this first appear: I didn't change anything when this happened. The first log of this issue occurred at 2023-09-14T18:16:17.796693324Z. Nothing before that log event indicates any issues. I was notified about it by a user who couldn't see messages from matrix.org at 2023-09-15T18:01:44Z.

Steps to reproduce

Create a room with a user from my server (genzedong.xyz) and one from matrix.org
Try sending messages to each other

Current Log Snippet (debug enabled)

time="2023-09-16T19:31:26.516746153Z" level=debug msg="Responding to sync since client gave up or timeout was reached" device_id=<redacted> limit=20 req.id=cQgHqYh7RRdG req.method=GET req.path=/_matrix/client/v3/sync since=s577333_73_912238_173441_575756_577335_412833_1193010_14193119 timeout=30s user_id="@<redacted>:genzedong.xyz"
time="2023-09-16T19:31:27.651506608Z" level=debug msg="Responding to sync immediately" currentPos=s577333_73_912238_173441_575756_577335_412833_1193010_14193167 device_id=<redacted> limit=20 req.id=um1KVbZnyV3k req.method=GET req.path=/_matrix/client/v3/sync since=s577333_73_912238_173441_575756_577335_412833_1193010_14193123 timeout=30s user_id="@<redacted>:genzedong.xyz"
time="2023-09-16T19:31:28.909637435Z" level=debug msg="Received transaction \"1694784743176\" from \"midnightthoughts.space\" containing 0 PDUs, 1 EDUs" req.id=b7yvUpU966cW req.method=PUT req.path=/_matrix/federation/v1/send/1694784743176
time="2023-09-16T19:31:32.196473255Z" level=info msg="Invalid request signature" error="Bad signature from \"matrix.org\" with ID \"ed25519:a_RXGa\"" req.id=BBjGvPFEYdHJ req.method=PUT req.path=/_matrix/federation/v1/send/1694707817017
time="2023-09-16T19:31:32.506150312Z" level=debug msg="Received transaction \"1688677502864\" from \"tdb.fi\" containing 0 PDUs, 1 EDUs" req.id=nkuWE52sulBm req.method=PUT req.path=/_matrix/federation/v1/send/1688677502864
time="2023-09-16T19:31:40.068640778Z" level=debug msg="Received transaction \"1694867998514\" from \"hicag.org\" containing 0 PDUs, 1 EDUs" req.id=oXHtJy6CeItZ req.method=PUT req.path=/_matrix/federation/v1/send/1694867998514
time="2023-09-16T19:31:41.766191718Z" level=debug msg="Received transaction \"1691411639696\" from \"speyhard.vip\" containing 0 PDUs, 1 EDUs" req.id=ahkQKbQR6ppu req.method=PUT req.path=/_matrix/federation/v1/send/1691411639696

Log Snippet from the first occurrence (debug disabled)

time="2023-09-14T18:16:01.023729615Z" level=info msg="Starting queue due to pending events or forceWakeup" func="github.com/matrix-org/dendrite/federationapi/queue.(*destinationQueue).wakeQueueIfEventsPending" file="github.com/matrix-org/dendrite/federationapi/queue/destinationqueue.go:160"
time="2023-09-14T18:16:05.405738258Z" level=info msg="Sending EDU event" func="github.com/matrix-org/dendrite/federationapi/queue.(*OutgoingQueues).SendEDU" file="github.com/matrix-org/dendrite/federationapi/queue/queue.go:331" destinations=1 edu_type=m.receipt
time="2023-09-14T18:16:09.996573435Z" level=info msg="Sending EDU event" func="github.com/matrix-org/dendrite/federationapi/queue.(*OutgoingQueues).SendEDU" file="github.com/matrix-org/dendrite/federationapi/queue/queue.go:331" destinations=1 edu_type=m.receipt 
time="2023-09-14T18:16:17.796693324Z" level=info msg="Invalid request signature" func=github.com/matrix-org/gomatrixserverlib/fclient.VerifyHTTPRequest file="github.com/matrix-org/gomatrixserverlib@v0.0.0-20230807152937-c48e302e15ac/fclient/request.go:263" error="Bad signature from \"matrix.org\" with ID \"ed25519:a_RXGa\"" req.id=5sHcv4qFjzCy req.method=PUT req.path=/_matrix/federation/v1/send/1694705428413
time="2023-09-14T18:16:31.266005182Z" level=info msg="Sent event to roomserver" func=github.com/matrix-org/dendrite/clientapi/routing.SendEvent file="github.com/matrix-org/dendrite/clientapi/routing/sendevent.go:221" event_id="$l2PPYbcie7kzl_0JGGo1m2EGOqkzRsJCpRtd5xmgobQ" req.id=jZYofYSrnBJt req.method=PUT req.path="/_matrix/client/v3/rooms/!lxZskaweshRfTnWv:genzedong.xyz/send/m.room.encrypted/FluffyChat <redacted>" room_id="!lxZskaweshRfTnWv:genzedong.xyz" room_version=10 user_id="@<redacted>:genzedong.xyz"
time="2023-09-14T18:16:31.268984470Z" level=info msg="Sending event" func="github.com/matrix-org/dendrite/federationapi/queue.(*OutgoingQueues).SendEvent" file="github.com/matrix-org/dendrite/federationapi/queue/queue.go:235" destinations=1 event="$l2PPYbcie7kzl_0JGGo1m2EGOqkzRsJCpRtd5xmgobQ"
time="2023-09-14T18:16:33.050211423Z" level=info msg="Invalid request signature" func=github.com/matrix-org/gomatrixserverlib/fclient.VerifyHTTPRequest file="github.com/matrix-org/gomatrixserverlib@v0.0.0-20230807152937-c48e302e15ac/fclient/request.go:263" error="Bad signature from \"matrix.org\" with ID \"ed25519:a_RXGa\"" req.id=vLKoQ9EucciE req.method=PUT req.path=/_matrix/federation/v1/send/1694705428725

Elara6331 commented 1 year ago

The issue seems to have fixed itself when matrix.org's signature and valid_until_ts were refreshed. The homeserver is now receiving transactions from matrix.org again. I think it would be a good idea to figure out what caused this, but I don't know how to go about that since I can no longer reproduce the issue.

S7evinK commented 1 year ago

What is your value for global.cache.max_age? Wondering if this is maybe due a caching issue in combination with Dendrite being unable to fetch the keys from matrix.org

Elara6331 commented 1 year ago

What is your value for global.cache.max_age? Wondering if this is maybe due a caching issue in combination with Dendrite being unable to fetch the keys from matrix.org

That's set to 1h

S7evinK commented 1 year ago

Well, there goes my theory.

jjj333-p commented 11 months ago

okay as mentioned in #3278 https://github.com/matrix-org/gomatrixserverlib/commit/5dd581bf6b8f6eb962ea825b4e6bb763378e6cc4 seems to fix this. im told this should roll out soon, and i can attest that patching it in fixed the issue for me

matrix-org / dendrite