During auth for event X: found rejected event Y in the state

[TellowKrinkle]

Description

I run heisenbridge with a conduit-based matrix server to access some IRC channels using my Matrix client. I connect to that server using an account on matrix.org. Recently, a number of heisenbridge's puppeted users have gone missing from the channels they should be in, along with any messages they sent. Upon further inspection, it seems over half of the users that my matrix server thinks are in the rooms aren't in the rooms according to the federated matrix.org view. All the logs from my matrix server where it attempts to send a state update to https://matrix-federation.matrix.org/_matrix/federation/v1/send/xxx (including ones containing events that are never reflected in the matrix.org view of the rooms) return an HTTP 200. I tried a number of things trying to get the rooms in sync or to get an error message out of matrix.org, and finally when using my matrix.org account to invite one of the broken accounts to one of the rooms it wasn't showing up in, I got this:

{
    "errcode": "M_FORBIDDEN",
    "error": "During auth for event $QZxiK6BnzC0tDf4CrfjMqQ1COgehS0C9xRZK4lirbFE: found rejected event $D__XFUASEs1P11AmLg1ShHyET_dCtOkEbFfvkUP71DM in the state"
}

I assume this is also the reason those accounts never show up on matrix.org when they join the room on my matrix server.

Steps to reproduce

• Host a matrix server using conduit v0.8.0
• Set up heisenbridge with a matrix.org account as its owner
• Use heisenbridge to join all 7 asahi linux channels on irc.oftc.net
• Wait a few days
• Compare your matrix bridge to the irc logs on https://oftc.irclog.whitequark.org/asahi
• Notice that messages from a number of users are missing (note that I tried having heisenbridge leave all its rooms and create new ones, and they broke after a few days, so this does happen at least somewhat consistently)
• Manually log into your conduit server using heisenbridge's credentials (e.g. using a python repl and mautrix) and grant your matrix.org account admin privileges on the heisenbridge managed channels
• Log into your matrix.org account using element web
• Open the web inspector on element web
• Attempt to invite one of the users whose messages aren't showing up to the channel using your matrix.org account via element web
• Find the network request that was made to do the invite, and view its response

Homeserver

matrix.org

Synapse Version

1.115.0 (b=matrix-org-hotfixes,26ac069915)

Installation Method

I don't know

Database

Unknown (whatever matrix.org is using)

Workers

I don't know

Platform

matrix.org

Configuration

No response

Relevant log output

I'd guess most of the important logs are on matrix.org, hopefully someone has access to those?

Here's some logs from my matrix server as it sends an invite, join, and leave for a user to the matrix.org server, receiving an HTTP 200 each time, even though the events never show up for clients of the matrix.org room:

2024-09-23T04:01:18.328157Z DEBUG http_request{path=/_matrix/client/v3/rooms/:room_id/invite}: tower_http::trace::on_request: started processing request
2024-09-23T04:01:18.328476Z DEBUG http_request{path=/_matrix/client/v3/rooms/:room_id/invite}: conduit::api::ruma_wrapper::axum: Request { method: POST, uri: /_matrix/client/v3/rooms/%21bEgj6yQL0gBE9KHySz%3Amatrix.tellowkrinkle.com/invite?user_id=@heisenbridge:matrix.tellowkrinkle.com, version: HTTP/1.1, headers: {"host": "localhost:6167", "user-agent": "mautrix-python/0.20.4 aiohttp/3.9.5 Python/3.10.12", "authorization": Sensitive, "content-type": "application/json", "accept": "*/*", "accept-encoding": "gzip, deflate", "content-length": "52"}, body: [123, 34, 117, 115, 101, 114, 95, 105, 100, 34, 58, 34, 64, 105, 114, 99, 95, 111, 102, 116, 99, 95, 97, 114, 58, 109, 97, 116, 114, 105, 120, 46, 116, 101, 108, 108, 111, 119, 107, 114, 105, 110, 107, 108, 101, 46, 99, 111, 109, 34, 125] }
2024-09-23T04:01:18.328752Z  INFO http_request{path=/_matrix/client/v3/rooms/:room_id/invite}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","is_direct":false,"membership":"invite"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@heisenbridge:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: auth_check beginning for $thiswillbefilledinlater (m.room.member)
2024-09-23T04:01:18.328770Z  INFO http_request{path=/_matrix/client/v3/rooms/:room_id/invite}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","is_direct":false,"membership":"invite"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@heisenbridge:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: starting m.room.member check
2024-09-23T04:01:18.328786Z  INFO http_request{path=/_matrix/client/v3/rooms/:room_id/invite}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","is_direct":false,"membership":"invite"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@heisenbridge:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: m.room.member event was allowed
2024-09-23T04:01:18.331674Z DEBUG http_request{path=/_matrix/client/v3/sync}: tower_http::trace::on_response: finished processing request latency=8994 ms status=200
2024-09-23T04:01:18.331741Z DEBUG http_request{path=/_matrix/client/v3/rooms/:room_id/invite}: tower_http::trace::on_response: finished processing request latency=3 ms status=200
2024-09-23T04:01:18.333240Z DEBUG handle_events:send_request{registration=Registration { id: "heisenbridge", url: Some("http://127.0.0.1:9898"), as_token: "Sensitive", hs_token: "Sensitive", sender_localpart: "heisenbridge", namespaces: Namespaces { users: [Namespace { exclusive: true, regex: "@irc_.*" }], aliases: [], rooms: [] }, rate_limited: Some(false), protocols: None }}: hyper_util::client::legacy::connect::http: connecting to 127.0.0.1:9898
2024-09-23T04:01:18.333668Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Preparing to send request to matrix.org
2024-09-23T04:01:18.333848Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Preparing request body {"origin":"matrix.tellowkrinkle.com","origin_server_ts":1727064078333,"pdus":[{"auth_events":["$aabFFd_njBtph4rYbgFdZJoK92Zg78tUomYCcZPoJM8","$tmL87Gj3sxvtXhX63fEz6hDArS3jMlaJSrL8vbjYsVE","$d64wpfUpuZ5thjQp6nUjh6XTgotj-w4Zg86AKaGaWng","$88XWc0zH2Kte6WkxSJwJk9dXah05gCfMSf7Q9tmbboY","$AVRjWe0dtdJ3mXy_kNn6kzg3Pw7SuVsSSkH8YVGNbDI"],"content":{"displayname":"ar","is_direct":false,"membership":"invite"},"depth":919,"hashes":{"sha256":"j7SqONJZs+KGAxW+CA/+Y442P2JMtNlHPFlsiorINu8"},"origin":"matrix.tellowkrinkle.com","origin_server_ts":1727064078328,"prev_events":["$zFLV1DMngFqTNL-JWOAqsFb9Ybbd7cJL8k5GIWbY8GY"],"room_id":"!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com","sender":"@heisenbridge:matrix.tellowkrinkle.com","signatures":{"matrix.tellowkrinkle.com":{"ed25519:iq9NsCzI":"FdJTWVUng+JXfhgC+PF2aSAoiyhsYM0gqNMJbHLcy1j6KZ/eaWDK6re6LyFJObnS8ngmSCEFkkYIbjCy9MSCAQ"}},"state_key":"@irc_oftc_ar:matrix.tellowkrinkle.com","type":"m.room.member","unsigned":{"prev_content":{"displayname":"ar","membership":"leave"},"prev_sender":"@irc_oftc_ar:matrix.tellowkrinkle.com"}}]}
2024-09-23T04:01:18.334149Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Sending request to matrix.org at https://matrix-federation.matrix.org/_matrix/federation/v1/send/Q9Sa7x3-MKgXczU7rNNELJ_hEs7HPkjqzvJVMjhZhdQ
2024-09-23T04:01:18.334300Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="matrix-federation.matrix.org"
2024-09-23T04:01:18.335227Z DEBUG handle_events:send_request{destination="matrix.org"}: hyper_util::client::legacy::connect::http: connecting to 104.20.76.252:443
2024-09-23T04:01:18.337340Z DEBUG handle_events:send_request{destination="matrix.org"}: hyper_util::client::legacy::connect::http: connected to 104.20.76.252:443
2024-09-23T04:01:18.352064Z DEBUG http_request{path=/_matrix/client/v3/join/:room_id_or_alias}: tower_http::trace::on_request: started processing request
2024-09-23T04:01:18.352388Z DEBUG http_request{path=/_matrix/client/v3/join/:room_id_or_alias}: conduit::api::ruma_wrapper::axum: Request { method: POST, uri: /_matrix/client/v3/join/%21bEgj6yQL0gBE9KHySz%3Amatrix.tellowkrinkle.com?user_id=@irc_oftc_ar:matrix.tellowkrinkle.com, version: HTTP/1.1, headers: {"host": "localhost:6167", "user-agent": "mautrix-python/0.20.4 aiohttp/3.9.5 Python/3.10.12", "authorization": Sensitive, "content-type": "application/json", "accept": "*/*", "accept-encoding": "gzip, deflate", "content-length": "2"}, body: [123, 125] }
2024-09-23T04:01:18.352534Z  INFO http_request{path=/_matrix/client/v3/join/:room_id_or_alias}: conduit::api::client_server::membership: We can join locally
2024-09-23T04:01:18.352913Z  INFO http_request{path=/_matrix/client/v3/join/:room_id_or_alias}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","membership":"join"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@irc_oftc_ar:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: auth_check beginning for $thiswillbefilledinlater (m.room.member)
2024-09-23T04:01:18.352933Z  INFO http_request{path=/_matrix/client/v3/join/:room_id_or_alias}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","membership":"join"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@irc_oftc_ar:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: starting m.room.member check
2024-09-23T04:01:18.352949Z  INFO http_request{path=/_matrix/client/v3/join/:room_id_or_alias}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","membership":"join"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@irc_oftc_ar:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: m.room.member event was allowed
2024-09-23T04:01:18.354993Z DEBUG http_request{path=/_matrix/client/v3/join/:room_id_or_alias}: tower_http::trace::on_response: finished processing request latency=2 ms status=200
2024-09-23T04:01:18.355910Z DEBUG http_request{path=/_matrix/client/v3/rooms/:room_id/leave}: tower_http::trace::on_request: started processing request
2024-09-23T04:01:18.356193Z DEBUG http_request{path=/_matrix/client/v3/rooms/:room_id/leave}: conduit::api::ruma_wrapper::axum: Request { method: POST, uri: /_matrix/client/v3/rooms/%21bEgj6yQL0gBE9KHySz%3Amatrix.tellowkrinkle.com/leave?user_id=@irc_oftc_ar:matrix.tellowkrinkle.com, version: HTTP/1.1, headers: {"host": "localhost:6167", "user-agent": "mautrix-python/0.20.4 aiohttp/3.9.5 Python/3.10.12", "authorization": Sensitive, "content-type": "application/json", "accept": "*/*", "accept-encoding": "gzip, deflate", "content-length": "2"}, body: [123, 125] }
2024-09-23T04:01:18.356592Z  INFO http_request{path=/_matrix/client/v3/rooms/:room_id/leave}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","membership":"leave"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@irc_oftc_ar:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: auth_check beginning for $thiswillbefilledinlater (m.room.member)
2024-09-23T04:01:18.356614Z  INFO http_request{path=/_matrix/client/v3/rooms/:room_id/leave}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","membership":"leave"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@irc_oftc_ar:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: starting m.room.member check
2024-09-23T04:01:18.356627Z  INFO http_request{path=/_matrix/client/v3/rooms/:room_id/leave}:build_and_append_pdu{pdu_builder=PduBuilder { event_type: "m.room.member", content: RawValue({"displayname":"ar","membership":"leave"}), unsigned: None, state_key: Some("@irc_oftc_ar:matrix.tellowkrinkle.com"), redacts: None } sender="@irc_oftc_ar:matrix.tellowkrinkle.com" room_id="!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com"}: ruma_state_res::event_auth: m.room.member event was allowed
2024-09-23T04:01:18.358513Z DEBUG http_request{path=/_matrix/client/v3/rooms/:room_id/leave}: tower_http::trace::on_response: finished processing request latency=2 ms status=200
2024-09-23T04:01:18.513517Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Received response from matrix.org at https://matrix-federation.matrix.org/_matrix/federation/v1/send/Q9Sa7x3-MKgXczU7rNNELJ_hEs7HPkjqzvJVMjhZhdQ
2024-09-23T04:01:18.513850Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Getting response bytes from matrix.org
2024-09-23T04:01:18.513933Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Got response bytes from matrix.org: {"pdus":{"$TCe9ajmy4ZV0zUuxqL-Aq_R17ar7IGqg-OzGPKejnnA":{}}}
2024-09-23T04:01:18.513940Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Parsing response bytes from matrix.org
2024-09-23T04:01:18.514560Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Preparing to send request to matrix.org
2024-09-23T04:01:18.514632Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Preparing request body {"origin":"matrix.tellowkrinkle.com","origin_server_ts":1727064078514,"pdus":[{"auth_events":["$tmL87Gj3sxvtXhX63fEz6hDArS3jMlaJSrL8vbjYsVE","$aabFFd_njBtph4rYbgFdZJoK92Zg78tUomYCcZPoJM8","$TCe9ajmy4ZV0zUuxqL-Aq_R17ar7IGqg-OzGPKejnnA","$AVRjWe0dtdJ3mXy_kNn6kzg3Pw7SuVsSSkH8YVGNbDI"],"content":{"displayname":"ar","membership":"join"},"depth":920,"hashes":{"sha256":"lsZLAnGFtKat/mxFWCPq8od9GQeRuYrZkNkje8TWoHQ"},"origin":"matrix.tellowkrinkle.com","origin_server_ts":1727064078352,"prev_events":["$TCe9ajmy4ZV0zUuxqL-Aq_R17ar7IGqg-OzGPKejnnA"],"room_id":"!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com","sender":"@irc_oftc_ar:matrix.tellowkrinkle.com","signatures":{"matrix.tellowkrinkle.com":{"ed25519:iq9NsCzI":"jK/3fWRpzPqDNAQ7OK2cfykVRYdZeUSLh8q/c/CiaRH/tlBicjBPhU6DWPE4PrxsmzvBKWHpAACKCrh5uqx0BQ"}},"state_key":"@irc_oftc_ar:matrix.tellowkrinkle.com","type":"m.room.member","unsigned":{"prev_content":{"displayname":"ar","is_direct":false,"membership":"invite"},"prev_sender":"@heisenbridge:matrix.tellowkrinkle.com"}},{"auth_events":["$tmL87Gj3sxvtXhX63fEz6hDArS3jMlaJSrL8vbjYsVE","$kJrF1vk2tA3GtDaKMqM_ZolAsdGN1INZEsCxSBJiG7U","$aabFFd_njBtph4rYbgFdZJoK92Zg78tUomYCcZPoJM8"],"content":{"displayname":"ar","membership":"leave"},"depth":921,"hashes":{"sha256":"GXzow3E1sDerGxQ60nyZsugcHNd2QxPHEAFWBpAZ/i8"},"origin":"matrix.tellowkrinkle.com","origin_server_ts":1727064078356,"prev_events":["$kJrF1vk2tA3GtDaKMqM_ZolAsdGN1INZEsCxSBJiG7U"],"room_id":"!bEgj6yQL0gBE9KHySz:matrix.tellowkrinkle.com","sender":"@irc_oftc_ar:matrix.tellowkrinkle.com","signatures":{"matrix.tellowkrinkle.com":{"ed25519:iq9NsCzI":"Tm+aWeN/2gn2IHBK9/bmoW6qpJU2cHozccGWHeDnHwYhlAbclgpln8nlVbyUbQEUkxlMr1fk7y/j1bbSjh98CQ"}},"state_key":"@irc_oftc_ar:matrix.tellowkrinkle.com","type":"m.room.member","unsigned":{"prev_content":{"displayname":"ar","membership":"join"},"prev_sender":"@irc_oftc_ar:matrix.tellowkrinkle.com"}}]}
2024-09-23T04:01:18.514891Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Sending request to matrix.org at https://matrix-federation.matrix.org/_matrix/federation/v1/send/is4PWF_0eX7yUuA0NMX2kK4F7Ro5mNTP1GUyeh_0fc4
2024-09-23T04:01:18.514956Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="matrix-federation.matrix.org"
2024-09-23T04:01:18.515691Z DEBUG handle_events:send_request{destination="matrix.org"}: hyper_util::client::legacy::connect::http: connecting to 104.20.77.252:443
2024-09-23T04:01:18.517536Z DEBUG handle_events:send_request{destination="matrix.org"}: hyper_util::client::legacy::connect::http: connected to 104.20.77.252:443
2024-09-23T04:01:18.730203Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Received response from matrix.org at https://matrix-federation.matrix.org/_matrix/federation/v1/send/is4PWF_0eX7yUuA0NMX2kK4F7Ro5mNTP1GUyeh_0fc4
2024-09-23T04:01:18.730242Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Getting response bytes from matrix.org
2024-09-23T04:01:18.730332Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Got response bytes from matrix.org: {"pdus":{"$kJrF1vk2tA3GtDaKMqM_ZolAsdGN1INZEsCxSBJiG7U":{},"$hXX_GusX02ExJ0H6MjTPleRfgOnSATRCCpW6oo5AcCc":{}}}
2024-09-23T04:01:18.730339Z DEBUG handle_events:send_request{destination="matrix.org"}: conduit::api::server_server: Parsing response bytes from matrix.org

Anything else that would be useful to know?

No response