"Your server isn't divulging details about prev_events referenced in this event" upon join, when other servers create events without incrementing `depth`

[progval]

Description

Under some circumstances involving a custom resident homeserver, Synapse rejects the join of another homeserver, as well as the first m.room.message following the join, with "Your server isn't divulging details about prev_events referenced in this event", even though it successfully persisted these prev_events.

Most curiously, this goes away if either:

1. if hs-s sends two messages instead of one only errors on the join, then manages to recover from the error when receiving the two PDUs with m.room.message (even though both are sent in the same transaction)
2. if hs-r is running any commit before ecb6fe9 then the error does not happen at all

Steps to reproduce

1. custom homeserver hs-c creates a room
2. Synapse hs-r joins it (make_join + send_join to hs-c)
3. Synapse hs-s joins it (ditto; and it sees hs-r's m.room.member in make_join's reply); hc-c forwards it to hs-r
4. hs-s then sends a m.room.message to the room
5. Client waits forever for hs-r to get the message

hs-r then fails to process both events from hs-s with: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.

Here is an example session (c-r and c-s are shorthands for @receiver:hs-c and @sender:hs-s).

First, hs-r joins the room as expected:

 c-r -> hs-r: POST http://localhost:34745/_matrix/client/v3/join/%23testroom%3Ahs-c.localhost%3A49005

hs-r -> hc-c: GET /_matrix/federation/v1/query/directory?room_alias=%23testroom%3Ahs-c.localhost%3A49005
hs-c -> hs-r: HTTP/1.1" 200 - { "room_id": "!roomid:hs-c.localhost:49005", "servers": [ "hs-c.localhost:49005" ] }

hs-r -> hs-c: GET /_matrix/federation/v1/make_join/%21roomid%3Ahs-c.localhost%3A49005/%40receiver%3Ahs-r.localhost%3A37051?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=org.matrix.msc2176&ver=7&ver=8&ver=9&ver=org.matrix.msc3787&ver=10&ver=org.matrix.msc2716v4
hc-c -> hs-r: HTTP/1.1" 200 -
    {
      "event": {
        "auth_events": [
          "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
          "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc",
          "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
        ],
        "depth": 0,
        "prev_events": [ "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I" ],
        "content": { "membership": "join" },
        "origin": "example.org",
        "origin_server_ts": 1679676912146,
        "room_id": "!roomid:hs-c.localhost:49005",
        "sender": "@receiver:hs-r.localhost:37051",
        "state_key": "@receiver:hs-r.localhost:37051",
        "type": "m.room.member"
      },
      "room_version": "9"
    }

[omitted: request to v2 send_join errors with 400 M_UNRECOGNIZED]

hs-r -> hs-c: PUT https://hs-c.localhost:49005/_matrix/federation/v1/send_join/%21roomid%3Ahs-c.localhost%3A49005/%24XIUf0Jg_6IW7ScFWOsQd83kQX69w3L4Z-UAECIj-sCo
    {
      "auth_events": [
        "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
        "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc",
        "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
      ],
      "content": { "avatar_url": null, "displayname": "receiver", "membership": "join" },
      "depth": 0,
      "hashes": { "sha256": "08fI2+ZK3iHS7v5BUEsmAuDnCGVVw91OoPCO53TUsFc" },
      "origin": "hs-r.localhost:37051",
      "origin_server_ts": 1679676912146,
      "prev_events": [ "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I" ],
      "room_id": "!roomid:hs-c.localhost:49005",
      "sender": "@receiver:hs-r.localhost:37051",
      "signatures": { "hs-r.localhost:37051": { "ed25519:a_mpCA": "+1KgWZ995c2z0Z2Tv6fWRr7lpxqjXjSsYzoGMsNvpzUVZGQwb2LqAxyDDXIkP4RrzH+dYibVLDHcX41nxaWzCQ" } },
      "state_key": "@receiver:hs-r.localhost:37051",
      "type": "m.room.member",
      "unsigned": { "age": 1 }
    }
hs-c -> hs-r:HTTP/1.1" 200 -
->  [
      200,
      {
        "auth_chain": [ ],
        "origin": "hs-c.localhost:49005",
        "state": [
          {
            "auth_events": [ ],
            "depth": 0,
            "prev_events": [ ],
            "content": { "creator": "@creator:hs-c.localhost:49005", "room_version": "9" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.create",
            "hashes": { "sha256": "JBn9JBE0nuiPgoNdmfOVJtmO3FDSTogFUuT+uqxt2XA" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "TzmRDngHKWgkzj4cVAnsZySQr+Ppv8XM+yG1XhpWdbYPTPuGtPZHPsnCOrrORQDG8vCimOJRPtgD8ge6ZyePAA" } }
          } /* X event id: $HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI */,
          {
            "auth_events": [ "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI" ],
            "depth": 0,
            "prev_events": [ "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI" ],
            "content": { "membership": "join" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "@creator:hs-c.localhost:49005",
            "type": "m.room.member",
            "hashes": { "sha256": "V15kvJOsf2PZXTPUzmUEI/zyyeKZxzKjLKr59jmC6qE" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "Z7mwmLtzXPZ1QhjvcP8QlNK0/M8wgBXGBDfl4hKXdhsfsz4dGCezIaUlxC16CktfMWHhS031FFP+uR40bIjoCg" } }
          } /* X event id: $5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU */,
          {
            "auth_events": [ "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI", "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU" ],
            "depth": 0,
            "prev_events": [ "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU" ],
            "content": {
              "ban": 50,
              "events": { "m.room.name": 100, "m.room.power_levels": 100 },
              "events_default": 0,
              "invite": 50,
              "kick": 50,
              "notifications": { "room": 20 },
              "redact": 50,
              "state_default": 50,
              "users": { "@creator:hs-c.localhost:49005": 100 },
              "users_default": 0
            },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.power_levels",
            "hashes": { "sha256": "Zlbuqzb+PzM9xkSYrlobEgXWEtKMGSy4dm9/ygIKIXU" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "ADU+fZWY6mBWdr28N7g2zH+Q/4hmPf3cErLVr1lLuPHwFFsqIrRBioN+A3N2aRszYIrIEkn3TlqvpBbKS4JbAw" } }
          } /* X event id: $jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            ],
            "depth": 0,
            "prev_events": [ "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc" ],
            "content": { "join_rule": "public" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.join_rules",
            "hashes": { "sha256": "fHTo5qMD0tLMEMANGd5kwh3GOk8a5wOVP5U0f+Q3f3w" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "nludaLrT3J/6Ink4TomFjBeAS2pI9XrX4VBq5axXqdLWmmRXJ5UWzOyZKWBo2/Kjj6v8H4oPpurhldySCrLeCw" } }
          } /* X event id: $lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            ],
            "depth": 0,
            "prev_events": [ "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc" ],
            "content": { "alias": "#testroom:hs-c.localhost:49005" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.canonical_alias",
            "hashes": { "sha256": "v1le6vfPC/vmWXLKLXGAtVIGgttd23y6rv13ZAUf6aU" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "iyD6iPwZWhftvgQA+C/vD30NttPCS/W4/tleZ6Z7rEjDoNuGrgY8MQN/ByLwi1CA5wqNs1aMpfVtce6YJFwTBQ" } }
          } /* X event id: $xJWTNqWJBy-2nD6sLscd1q3A1OchNHCk0PdFzHGfwQ0 */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            ],
            "depth": 0,
            "prev_events": [ "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc" ],
            "content": { "history_visibility": "world_readable" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.history_visibility",
            "hashes": { "sha256": "46eI0CqnYJET/yOTfI/UCgKXuKW20HQ4io03iLzryaM" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "/OA1wH0G7UBvZ+0ughwdHYCx7tdD49IrO7k66EpAYWEKBPqH4zgV5fI5SdtXrs4hJYlzTiaqeX1LM56bPkG2DQ" } }
          } /* X event id: $BY9oFN0QkzjKrAcK_LtMoUUTqPYl9Q8HLTyo9CF1k4c */
        ]
      }
    ]



hs-r -> hs-c: GET /_matrix/key/v2/server
hs-c -> hr-r: HTTP/1.1" 200 -
    {
      "server_name": "hs-c.localhost:49005",
      "verify_keys": { "ed25519:1": { "key": "X4U4vyfvBTyE/Wneqgimltt+VZYspRgRWh+Yy8ONZms" } },
      "old_verify_keys": { },
      "valid_until_ts": 1679680514519,
      "signatures": { "hs-c.localhost:49005": { "ed25519:1": "f+ndbmatFQcVbEdZAQKJ1qtQf9Bti0om7b2CXcdyKm6FcHd+taJpnqtbHMwagqCRE2JVZYUck/VVBkrWKBWSCg" } }
    }

hs-r -> c-r : 200
    { "room_id": "!roomid:hs-c.localhost:49005" }

 c-r -> hs-r: GET /_matrix/client/v3/sync?timeout=1000
hs-r -> c-r : 200
{
  "next_batch": "s2_1_0_1_1_1_1_2_0",
  "account_data": {
    "events": [
      {
        "type": "m.push_rules",
        "content": {
          /* redacted */
        }
      }
    ]
  },
  "device_one_time_keys_count": { "signed_curve25519": 0 },
  "org.matrix.msc2732.device_unused_fallback_key_types": [ ],
  "device_unused_fallback_key_types": [ ],
  "rooms": {
    "join": {
      "!roomid:hs-c.localhost:49005": {
        "timeline": {
          "events": [
            {
              "content": { "membership": "join", "displayname": "receiver", "avatar_url": null },
              "origin_server_ts": 1679676912146,
              "sender": "@receiver:hs-r.localhost:37051",
              "state_key": "@receiver:hs-r.localhost:37051",
              "type": "m.room.member",
              "unsigned": { "age": 158 },
              "event_id": "$XIUf0Jg_6IW7ScFWOsQd83kQX69w3L4Z-UAECIj-sCo"
            }
          ],
          "prev_batch": "s2_1_0_1_1_1_1_2_0",
          "limited": false
        },
        "state": {
          "events": [
            {
              "content": { "join_rule": "public" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.join_rules",
              "unsigned": { },
              "event_id": "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
            },
            {
              "content": {
                "ban": 50,
                "events": { "m.room.name": 100, "m.room.power_levels": 100 },
                "events_default": 0,
                "invite": 50,
                "kick": 50,
                "notifications": { "room": 20 },
                "redact": 50,
                "state_default": 50,
                "users": { "@creator:hs-c.localhost:49005": 100 },
                "users_default": 0
              },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.power_levels",
              "unsigned": { },
              "event_id": "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            },
            {
              "content": { "creator": "@creator:hs-c.localhost:49005", "room_version": "9" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.create",
              "unsigned": { },
              "event_id": "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI"
            },
            {
              "content": { "membership": "join" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "@creator:hs-c.localhost:49005",
              "type": "m.room.member",
              "unsigned": { },
              "event_id": "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU"
            },
            {
              "content": { "alias": "#testroom:hs-c.localhost:49005" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.canonical_alias",
              "unsigned": { },
              "event_id": "$xJWTNqWJBy-2nD6sLscd1q3A1OchNHCk0PdFzHGfwQ0"
            },
            {
              "content": { "history_visibility": "world_readable" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.history_visibility",
              "unsigned": { },
              "event_id": "$BY9oFN0QkzjKrAcK_LtMoUUTqPYl9Q8HLTyo9CF1k4c"
            }
          ]
        },
        "account_data": { "events": [ ] },
        "ephemeral": { "events": [ ] },
        "unread_notifications": { "notification_count": 0, "highlight_count": 0 },
        "summary": { }
      }
    }
  }
}

Note that the above contains event $lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I (it's the join_rules at the beginning of the state event array); it's the event it will later pretend not to know.

Then @sender:hs-s registers and joins the room, ending with:

hs-s -> hs-c: PUT https://hs-c.localhost:49005/_matrix/federation/v1/send_join/%21roomid%3Ahs-c.localhost%3A49005/%24y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI
    {
      "auth_events": [
        "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
        "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc",
        "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
      ],
      "content": { "avatar_url": null, "displayname": "sender", "membership": "join" },
      "depth": 0,
      "hashes": { "sha256": "sImI4ZSewzfFMpwUwe07tqlBlPdbyiABi7OvOB6I6Mc" },
      "origin": "hs-s.localhost:51845",
      "origin_server_ts": 1679676912146,
      "prev_events": [ "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I" ],
      "room_id": "!roomid:hs-c.localhost:49005",
      "sender": "@sender:hs-s.localhost:51845",
      "signatures": { "hs-s.localhost:51845": { "ed25519:a_FCBT": "KmOlxIkUq2UJSnZIxso7G9ZY4592ZXl4Y/Z26wq9tBcY+w6WHeR3McX7KiNLeuUOmLBiOKHor5UJKmiKrgsPDg" } },
      "state_key": "@sender:hs-s.localhost:51845",
      "type": "m.room.member",
      "unsigned": { "age": 1 }
    } /* X event id: $y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI */

hs-c -> hs-r: hs-r.localhost:37051 PUT /_matrix/federation/v1/send/b0d1940b-be62-4f2a-8ebb-3b03e0d74718
	{
	  "edus": [ ],
	  "origin": "hs-r.localhost:37051",
	  "origin_server_ts": 1679676914929,
	  "pdus": [
	    {
	      "auth_events": [
		"$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
		"$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc",
		"$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
	      ],
	      "content": { "avatar_url": null, "displayname": "sender", "membership": "join" },
	      "depth": 0,
	      "hashes": { "sha256": "sImI4ZSewzfFMpwUwe07tqlBlPdbyiABi7OvOB6I6Mc" },
	      "origin": "hs-s.localhost:51845",
	      "origin_server_ts": 1679676912146,
	      "prev_events": [ "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I" ],
	      "room_id": "!roomid:hs-c.localhost:49005",
	      "sender": "@sender:hs-s.localhost:51845",
	      "signatures": { "hs-s.localhost:51845": { "ed25519:a_FCBT": "KmOlxIkUq2UJSnZIxso7G9ZY4592ZXl4Y/Z26wq9tBcY+w6WHeR3McX7KiNLeuUOmLBiOKHor5UJKmiKrgsPDg" } },
	      "state_key": "@sender:hs-s.localhost:51845",
	      "type": "m.room.member",
	      "unsigned": { "age": 1 }
	    } /* X event id: $y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI */
	  ]
	}

hs-r logs:
	hs-r.localhost:37051 17:55:14 DEBUG synapse.access.http.34745 - PUT-5 - ::1 - 34745 - Received request: PUT /_matrix/federation/v1/send/b0d1940b-be62-4f2a-8ebb-3b03e0d74718
	hs-r.localhost:37051 17:55:14 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-2 - {GET-O-7} [hs-c.localhost:49005] Sending request: GET matrix://hs-c.localhost:49005/_matrix/key/v2/server; timeout 10.000000s
	hs-r.localhost:37051 17:55:14 DEBUG synapse.http.federation.matrix_federation_agent - ServerKeyFetcher-2 - Connecting to hs-c.localhost:49005

hs-r -> hs-c: /_matrix/key/v2/server
hs-c -> hs-r: HTTP/1.1" 200 -
    {
      "server_name": "hs-c.localhost:49005",
      "verify_keys": { "ed25519:1": { "key": "X4U4vyfvBTyE/Wneqgimltt+VZYspRgRWh+Yy8ONZms" } },
      "old_verify_keys": { },
      "valid_until_ts": 1679680514936,
      "signatures": { "hs-c.localhost:49005": { "ed25519:1": "qpaVZ4Ndu9zA/z+2n9XNYwjGiZhPcZs3O3UB/FTwFTWlmcBudFiR0KhMV9fBny0eJT9kZyzLqe47xlIwtC1SDA" } }
    }

hs-r and hs-s logs:
	hs-r.localhost:37051 17:55:14 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-2 - {GET-O-7} [hs-c.localhost:49005] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:14 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-2 - {GET-O-7} [hs-c.localhost:49005] Completed request: 200 OK in 0.01 secs, got 326 bytes - GET matrix://hs-c.localhost:49005/_matrix/key/v2/server
	hs-r.localhost:37051 17:55:14 INFO synapse.federation.transport.server.federation - PUT-5 - Received txn b0d1940b-be62-4f2a-8ebb-3b03e0d74718 from hs-c.localhost:49005. (PDUs: 1, EDUs: 0)
	hs-r.localhost:37051 17:55:14 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-3 - {GET-O-8} [hs-s.localhost:51845] Sending request: GET matrix://hs-s.localhost:51845/_matrix/key/v2/server; timeout 10.000000s
	hs-r.localhost:37051 17:55:14 DEBUG synapse.http.federation.matrix_federation_agent - ServerKeyFetcher-3 - Connecting to hs-s.localhost:51845
	hs-s.localhost:51845 17:55:14 DEBUG synapse.access.https.51845 - GET-3 - ::1 - 51845 - Received request: GET /_matrix/key/v2/server
	hs-s.localhost:51845 17:55:14 INFO synapse.access.https.51845 - GET-3 - ::1 - 51845 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-3 - {GET-O-8} [hs-s.localhost:51845] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-3 - {GET-O-8} [hs-s.localhost:51845] Completed request: 200 OK in 0.06 secs, got 323 bytes - GET matrix://hs-s.localhost:51845/_matrix/key/v2/server
	hs-r.localhost:37051 17:55:15 INFO synapse.federation.federation_server - _process_incoming_pdus_in_room_inner-0 - handling received PDU in room !roomid:hs-c.localhost:49005: <FrozenEventV3 event_id=$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI, type=m.room.member, state_key=@sender:hs-s.localhost:51845, outlier=False>
	hs-r.localhost:37051 17:55:15 INFO synapse.access.http.34745 - PUT-5 - ::1 - 34745 - {hs-c.localhost:49005} Processed request: 0.087sec/0.001sec (0.001sec, 0.001sec) (0.002sec/0.009sec/6) 60B 200 "PUT /_matrix/federation/v1/send/b0d1940b-be62-4f2a-8ebb-3b03e0d74718 HTTP/1.1" "Python-urllib/3.11" [0 dbevts]

hs-r -> hs-c:
	{ "pdus": { "$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI": { } } }

hs-r logs:
	::1 - - [24/Mar/2023 17:55:15] "PUT /_matrix/federation/v1/send_join/%21roomid%3Ahs-c.localhost%3A49005/%24y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI HTTP/1.1" 200 -
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - POST-2 - {PUT-O-4} [hs-c.localhost:49005] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 WARNING synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-0-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI - Rejecting: failed to fetch 1 prev events: ['$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I']
	hs-r.localhost:37051 17:55:15 WARNING synapse.federation.federation_server - _process_incoming_pdus_in_room_inner-0 - Error handling PDU $y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.

First instance of the error ^

And then hs-s and hs-c complete the join:

hs-c -> hs-s:
    [
      200,
      {
        "auth_chain": [ ],
        "origin": "hs-c.localhost:49005",
        "state": [
          {
            "auth_events": [ ],
            "depth": 0,
            "prev_events": [ ],
            "content": { "creator": "@creator:hs-c.localhost:49005", "room_version": "9" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.create",
            "hashes": { "sha256": "JBn9JBE0nuiPgoNdmfOVJtmO3FDSTogFUuT+uqxt2XA" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "TzmRDngHKWgkzj4cVAnsZySQr+Ppv8XM+yG1XhpWdbYPTPuGtPZHPsnCOrrORQDG8vCimOJRPtgD8ge6ZyePAA" } }
          } /* X event id: $HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI */,
          {
            "auth_events": [ "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI" ],
            "depth": 0,
            "prev_events": [ "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI" ],
            "content": { "membership": "join" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "@creator:hs-c.localhost:49005",
            "type": "m.room.member",
            "hashes": { "sha256": "V15kvJOsf2PZXTPUzmUEI/zyyeKZxzKjLKr59jmC6qE" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "Z7mwmLtzXPZ1QhjvcP8QlNK0/M8wgBXGBDfl4hKXdhsfsz4dGCezIaUlxC16CktfMWHhS031FFP+uR40bIjoCg" } }
          } /* X event id: $5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU */,
          {
            "auth_events": [ "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI", "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU" ],
            "depth": 0,
            "prev_events": [ "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU" ],
            "content": {
              "ban": 50,
              "events": { "m.room.name": 100, "m.room.power_levels": 100 },
              "events_default": 0,
              "invite": 50,
              "kick": 50,
              "notifications": { "room": 20 },
              "redact": 50,
              "state_default": 50,
              "users": { "@creator:hs-c.localhost:49005": 100 },
              "users_default": 0
            },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.power_levels",
            "hashes": { "sha256": "Zlbuqzb+PzM9xkSYrlobEgXWEtKMGSy4dm9/ygIKIXU" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "ADU+fZWY6mBWdr28N7g2zH+Q/4hmPf3cErLVr1lLuPHwFFsqIrRBioN+A3N2aRszYIrIEkn3TlqvpBbKS4JbAw" } }
          } /* X event id: $jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            ],
            "depth": 0,
            "prev_events": [ "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc" ],
            "content": { "join_rule": "public" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.join_rules",
            "hashes": { "sha256": "fHTo5qMD0tLMEMANGd5kwh3GOk8a5wOVP5U0f+Q3f3w" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "nludaLrT3J/6Ink4TomFjBeAS2pI9XrX4VBq5axXqdLWmmRXJ5UWzOyZKWBo2/Kjj6v8H4oPpurhldySCrLeCw" } }
          } /* X event id: $lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            ],
            "depth": 0,
            "prev_events": [ "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc" ],
            "content": { "alias": "#testroom:hs-c.localhost:49005" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.canonical_alias",
            "hashes": { "sha256": "v1le6vfPC/vmWXLKLXGAtVIGgttd23y6rv13ZAUf6aU" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "iyD6iPwZWhftvgQA+C/vD30NttPCS/W4/tleZ6Z7rEjDoNuGrgY8MQN/ByLwi1CA5wqNs1aMpfVtce6YJFwTBQ" } }
          } /* X event id: $xJWTNqWJBy-2nD6sLscd1q3A1OchNHCk0PdFzHGfwQ0 */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            ],
            "depth": 0,
            "prev_events": [ "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc" ],
            "content": { "history_visibility": "world_readable" },
            "origin_server_ts": 1679676912146,
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@creator:hs-c.localhost:49005",
            "state_key": "",
            "type": "m.room.history_visibility",
            "hashes": { "sha256": "46eI0CqnYJET/yOTfI/UCgKXuKW20HQ4io03iLzryaM" },
            "signatures": { "hs-c.localhost:49005": { "ed25519:1": "/OA1wH0G7UBvZ+0ughwdHYCx7tdD49IrO7k66EpAYWEKBPqH4zgV5fI5SdtXrs4hJYlzTiaqeX1LM56bPkG2DQ" } }
          } /* X event id: $BY9oFN0QkzjKrAcK_LtMoUUTqPYl9Q8HLTyo9CF1k4c */,
          {
            "auth_events": [
              "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI",
              "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc",
              "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
            ],
            "content": { "avatar_url": null, "displayname": "receiver", "membership": "join" },
            "depth": 0,
            "hashes": { "sha256": "08fI2+ZK3iHS7v5BUEsmAuDnCGVVw91OoPCO53TUsFc" },
            "origin": "hs-r.localhost:37051",
            "origin_server_ts": 1679676912146,
            "prev_events": [ "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I" ],
            "room_id": "!roomid:hs-c.localhost:49005",
            "sender": "@receiver:hs-r.localhost:37051",
            "signatures": { "hs-r.localhost:37051": { "ed25519:a_mpCA": "+1KgWZ995c2z0Z2Tv6fWRr7lpxqjXjSsYzoGMsNvpzUVZGQwb2LqAxyDDXIkP4RrzH+dYibVLDHcX41nxaWzCQ" } },
            "state_key": "@receiver:hs-r.localhost:37051",
            "type": "m.room.member",
            "unsigned": { "age": 1 }
          } /* X event id: $XIUf0Jg_6IW7ScFWOsQd83kQX69w3L4Z-UAECIj-sCo */
        ]
      }
    ]

hs-s logs:
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - POST-2 - {PUT-O-4} [hs-c.localhost:49005] Completed request: 200 OK in 0.10 secs, got 4817 bytes - PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send_join/%21roomid%3Ahs-c.localhost%3A49005/%24y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI
	hs-s.localhost:51845 17:55:15 INFO synapse.federation.federation_client - POST-2 - Processing from send_join 7 events
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-0 - {GET-O-5} [hs-c.localhost:49005] Sending request: GET matrix://hs-c.localhost:49005/_matrix/key/v2/server; timeout 10.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.federation.matrix_federation_agent - ServerKeyFetcher-0 - Connecting to hs-c.localhost:49005
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-1 - {GET-O-6} [hs-r.localhost:37051] Sending request: GET matrix://hs-r.localhost:37051/_matrix/key/v2/server; timeout 10.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.federation.matrix_federation_agent - ServerKeyFetcher-1 - Connecting to hs-r.localhost:37051

hs-s -> hs-c: /_matrix/key/v2/server
hs-c -> hs-s: HTTP/1.1" 200 -
    {
      "server_name": "hs-c.localhost:49005",
      "verify_keys": { "ed25519:1": { "key": "X4U4vyfvBTyE/Wneqgimltt+VZYspRgRWh+Yy8ONZms" } },
      "old_verify_keys": { },
      "valid_until_ts": 1679680515032,
      "signatures": { "hs-c.localhost:49005": { "ed25519:1": "qImqwSMcj7uSGHZ/5UZOt/+tfn/ln4EaInJL2msrPp61lEaQC/zDnQ1BJ+lnBDYsB3nrKdpzO2Xphx1+BUk1Bw" } }
    }

hs-s and hs-r logs:
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-0 - {GET-O-5} [hs-c.localhost:49005] Got response headers: 200 OK
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-0 - {GET-O-5} [hs-c.localhost:49005] Completed request: 200 OK in 0.01 secs, got 326 bytes - GET matrix://hs-c.localhost:49005/_matrix/key/v2/server
	hs-r.localhost:37051 17:55:15 DEBUG synapse.access.https.37051 - GET-6 - ::1 - 37051 - Received request: GET /_matrix/key/v2/server
	hs-r.localhost:37051 17:55:15 INFO synapse.access.https.37051 - GET-6 - ::1 - 37051 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-1 - {GET-O-6} [hs-r.localhost:37051] Got response headers: 200 OK
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-1 - {GET-O-6} [hs-r.localhost:37051] Completed request: 200 OK in 0.02 secs, got 323 bytes - GET matrix://hs-r.localhost:37051/_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.handlers.federation_event - POST-2 - Persisting 1 of 7 remaining outliers: ['$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI']
	hs-s.localhost:51845 17:55:15 INFO synapse.handlers.federation_event - POST-2 - Persisting 1 of 6 remaining outliers: ['$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU']
	hs-s.localhost:51845 17:55:15 INFO synapse.handlers.federation_event - POST-2 - Persisting 1 of 5 remaining outliers: ['$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc']
	hs-s.localhost:51845 17:55:15 INFO synapse.handlers.federation_event - POST-2 - Persisting 3 of 4 remaining outliers: ['$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I', '$xJWTNqWJBy-2nD6sLscd1q3A1OchNHCk0PdFzHGfwQ0', '$BY9oFN0QkzjKrAcK_LtMoUUTqPYl9Q8HLTyo9CF1k4c']
	hs-s.localhost:51845 17:55:15 INFO synapse.handlers.federation_event - POST-2 - Persisting 1 of 1 remaining outliers: ['$XIUf0Jg_6IW7ScFWOsQd83kQX69w3L4Z-UAECIj-sCo']
	hs-s.localhost:51845 17:55:15 INFO synapse.handlers.federation_event - POST-2 - Peristing join-via-remote <FrozenEventV3 event_id=$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI, type=m.room.member, state_key=@sender:hs-s.localhost:51845, outlier=False> (partial_state: False)
	hs-s.localhost:51845 17:55:15 INFO synapse.access.http.50071 - POST-2 - ::1 - 50071 - {@sender:hs-s.localhost:51845} Processed request: 0.227sec/0.000sec (0.003sec, 0.001sec) (0.004sec/0.014sec/21) 42B 200 "POST /_matrix/client/v3/join/%23testroom%3Ahs-c.localhost%3A49005 HTTP/1.1" "Python-urllib/3.11" [4 dbevts]

hs-s -> c-s : 200
	{ "room_id": "!roomid:hs-c.localhost:49005" }

 c-s -> hs-s: GET /_matrix/client/v3/sync?timeout=1000
hs-s -> c: 200
{
  "next_batch": "s2_1_0_1_1_1_1_2_0",
  "account_data": {
    "events": [
      {
        "type": "m.push_rules",
        "content": {
          /* redacted */
        }
      }
    ]
  },
  "device_one_time_keys_count": { "signed_curve25519": 0 },
  "org.matrix.msc2732.device_unused_fallback_key_types": [ ],
  "device_unused_fallback_key_types": [ ],
  "rooms": {
    "join": {
      "!roomid:hs-c.localhost:49005": {
        "timeline": {
          "events": [
            {
              "content": { "membership": "join", "displayname": "sender", "avatar_url": null },
              "origin_server_ts": 1679676912146,
              "sender": "@sender:hs-s.localhost:51845",
              "state_key": "@sender:hs-s.localhost:51845",
              "type": "m.room.member",
              "unsigned": { "age": 238 },
              "event_id": "$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI"
            }
          ],
          "prev_batch": "s2_1_0_1_1_1_1_2_0",
          "limited": false
        },
        "state": {
          "events": [
            {
              "content": { "membership": "join" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "@creator:hs-c.localhost:49005",
              "type": "m.room.member",
              "unsigned": { },
              "event_id": "$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU"
            },
            {
              "content": { "history_visibility": "world_readable" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.history_visibility",
              "unsigned": { },
              "event_id": "$BY9oFN0QkzjKrAcK_LtMoUUTqPYl9Q8HLTyo9CF1k4c"
            },
            {
              "content": { "creator": "@creator:hs-c.localhost:49005", "room_version": "9" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.create",
              "unsigned": { },
              "event_id": "$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI"
            },
            {
              "content": { "join_rule": "public" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.join_rules",
              "unsigned": { },
              "event_id": "$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I"
            },
            {
              "content": { "alias": "#testroom:hs-c.localhost:49005" },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.canonical_alias",
              "unsigned": { },
              "event_id": "$xJWTNqWJBy-2nD6sLscd1q3A1OchNHCk0PdFzHGfwQ0"
            },
            {
              "content": { "avatar_url": null, "displayname": "receiver", "membership": "join" },
              "origin_server_ts": 1679676912146,
              "sender": "@receiver:hs-r.localhost:37051",
              "state_key": "@receiver:hs-r.localhost:37051",
              "type": "m.room.member",
              "unsigned": { "age": 1 },
              "event_id": "$XIUf0Jg_6IW7ScFWOsQd83kQX69w3L4Z-UAECIj-sCo"
            },
            {
              "content": {
                "ban": 50,
                "events": { "m.room.name": 100, "m.room.power_levels": 100 },
                "events_default": 0,
                "invite": 50,
                "kick": 50,
                "notifications": { "room": 20 },
                "redact": 50,
                "state_default": 50,
                "users": { "@creator:hs-c.localhost:49005": 100 },
                "users_default": 0
              },
              "origin_server_ts": 1679676912146,
              "sender": "@creator:hs-c.localhost:49005",
              "state_key": "",
              "type": "m.room.power_levels",
              "unsigned": { },
              "event_id": "$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc"
            }
          ]
        },
        "account_data": { "events": [ ] },
        "ephemeral": { "events": [ ] },
        "unread_notifications": { "notification_count": 0, "highlight_count": 0 },
        "summary": { }
      }
    }
  }
}

Then @sender:hs-s sends a message:

 c-s -> hs-s: PUT http://localhost:50071/_matrix/client/v3/rooms/%21roomid%3Ahs-c.localhost%3A49005/send/m.room.message/d8b91459-9289-4d78-b727-fbbf8950c55a
    { "body": "hello world", "msgtype": "m.text" }
hs-s -> c-s : 200
    { "event_id": "$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A" }

logs from hs-s and hs-r:
	hs-r.localhost:37051 17:55:15 DEBUG synapse.access.http.34745 - GET-7 - ::1 - 34745 - Received request: GET /_matrix/client/v3/sync?since=s2_1_0_1_1_1_1_2_0&timeout=1000
	hs-s.localhost:51845 17:55:15 INFO synapse.federation.sender - process_event_queue_for_federation-1 - Unexpectedly did not have cached prev group for $spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A
	hs-s.localhost:51845 17:55:15 INFO synapse.federation.sender.transaction_manager - federation_transaction_transmission_loop-0 - TX [hs-r.localhost:37051] {1679676912667} Sending transaction [1679676912667], (PDUs: 1, EDUs: 0)
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - federation_transaction_transmission_loop-0 - {PUT-O-7} [hs-r.localhost:37051] Sending request: PUT matrix://hs-r.localhost:37051/_matrix/federation/v1/send/1679676912667; timeout 60.000000s
	hs-s.localhost:51845 17:55:15 INFO synapse.federation.sender.transaction_manager - federation_transaction_transmission_loop-1 - TX [hs-c.localhost:49005] {1679676912668} Sending transaction [1679676912668], (PDUs: 1, EDUs: 0)
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-8} [hs-c.localhost:49005] Sending request: PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send/1679676912668; timeout 60.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.federation.matrix_federation_agent - federation_transaction_transmission_loop-1 - Connecting to hs-c.localhost:49005
	hs-r.localhost:37051 17:55:15 DEBUG synapse.access.https.37051 - PUT-8 - ::1 - 37051 - Received request: PUT /_matrix/federation/v1/send/1679676912667
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-4 - {GET-O-9} [hs-s.localhost:51845] Sending request: GET matrix://hs-s.localhost:51845/_matrix/key/v2/server; timeout 10.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.access.https.51845 - GET-6 - ::1 - 51845 - Received request: GET /_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.access.https.51845 - GET-6 - ::1 - 51845 - {None} Processed request: 0.000sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-4 - {GET-O-9} [hs-s.localhost:51845] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-4 - {GET-O-9} [hs-s.localhost:51845] Completed request: 200 OK in 0.00 secs, got 323 bytes - GET matrix://hs-s.localhost:51845/_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-8} [hs-c.localhost:49005] Got response headers: 400 Bad Request
	hs-s.localhost:51845 17:55:15 WARNING synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-8} [hs-c.localhost:49005] Request failed: PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send/1679676912668: HttpResponseException('400: Bad Request')
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - Retrying request with trailing slash
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-9} [hs-c.localhost:49005] Sending request: PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send/1679676912668/; timeout 60.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.federation.matrix_federation_agent - federation_transaction_transmission_loop-1 - Connecting to hs-c.localhost:49005
	hs-r.localhost:37051 17:55:15 INFO synapse.federation.transport.server.federation - PUT-8 - Received txn 1679676912667 from hs-s.localhost:51845. (PDUs: 1, EDUs: 0)
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-5 - {GET-O-10} [hs-s.localhost:51845] Sending request: GET matrix://hs-s.localhost:51845/_matrix/key/v2/server; timeout 10.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.access.https.51845 - GET-7 - ::1 - 51845 - Received request: GET /_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.access.https.51845 - GET-7 - ::1 - 51845 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-5 - {GET-O-10} [hs-s.localhost:51845] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-5 - {GET-O-10} [hs-s.localhost:51845] Completed request: 200 OK in 0.00 secs, got 323 bytes - GET matrix://hs-s.localhost:51845/_matrix/key/v2/server

hs-s -> hs-c: /_matrix/federation/v1/send/1679676912668/
    /* redacted */
hs-c -> hs-s: 400
	{ "errcode": "M_UNRECOGNIZED", "error": "Unknown endpoint" }

logs:
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-8} [hs-c.localhost:49005] Got response headers: 400 Bad Request
	hs-s.localhost:51845 17:55:15 WARNING synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-8} [hs-c.localhost:49005] Request failed: PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send/1679676912668: HttpResponseException('400: Bad Request')
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - Retrying request with trailing slash
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-9} [hs-c.localhost:49005] Sending request: PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send/1679676912668/; timeout 60.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.federation.matrix_federation_agent - federation_transaction_transmission_loop-1 - Connecting to hs-c.localhost:49005
	hs-r.localhost:37051 17:55:15 INFO synapse.federation.transport.server.federation - PUT-8 - Received txn 1679676912667 from hs-s.localhost:51845. (PDUs: 1, EDUs: 0)
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-5 - {GET-O-10} [hs-s.localhost:51845] Sending request: GET matrix://hs-s.localhost:51845/_matrix/key/v2/server; timeout 10.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.access.https.51845 - GET-7 - ::1 - 51845 - Received request: GET /_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.access.https.51845 - GET-7 - ::1 - 51845 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-5 - {GET-O-10} [hs-s.localhost:51845] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-5 - {GET-O-10} [hs-s.localhost:51845] Completed request: 200 OK in 0.00 secs, got 323 bytes - GET matrix://hs-s.localhost:51845/_matrix/key/v2/server

hs-s -> hs-c: /_matrix/federation/v1/send/1679676912668/
    /* redacted */
hs-c -> hs-s: 400
    { "errcode": "M_UNRECOGNIZED", "error": "Unknown endpoint" }

logs:
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-9} [hs-c.localhost:49005] Got response headers: 400 Bad Request
	hs-s.localhost:51845 17:55:15 WARNING synapse.http.matrixfederationclient - federation_transaction_transmission_loop-1 - {PUT-O-9} [hs-c.localhost:49005] Request failed: PUT matrix://hs-c.localhost:49005/_matrix/federation/v1/send/1679676912668/: HttpResponseException('400: Bad Request')
	hs-s.localhost:51845 17:55:15 INFO synapse.federation.sender.transaction_manager - federation_transaction_transmission_loop-1 - TX [hs-c.localhost:49005] {1679676912668} got 400 response
	hs-s.localhost:51845 17:55:15 WARNING synapse.federation.sender.per_destination_queue - federation_transaction_transmission_loop-1 - TX [hs-c.localhost:49005] Received 400 response to transaction: 400: Bad Request
	hs-r.localhost:37051 17:55:15 INFO synapse.federation.federation_server - _process_incoming_pdus_in_room_inner-1 - handling received PDU in room !roomid:hs-c.localhost:49005: <FrozenEventV3 event_id=$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A, type=m.room.message, state_key=None, outlier=False>
	hs-r.localhost:37051 17:55:15 INFO synapse.access.https.37051 - PUT-8 - ::1 - 37051 - {hs-s.localhost:51845} Processed request: 0.028sec/0.001sec (0.001sec, 0.000sec) (0.001sec/0.010sec/5) 60B 200 "PUT /_matrix/federation/v1/send/1679676912667 HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - federation_transaction_transmission_loop-0 - {PUT-O-7} [hs-r.localhost:37051] Got response headers: 200 OK
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - federation_transaction_transmission_loop-0 - {PUT-O-7} [hs-r.localhost:37051] Completed request: 200 OK in 0.03 secs, got 60 bytes - PUT matrix://hs-r.localhost:37051/_matrix/federation/v1/send/1679676912667
	hs-s.localhost:51845 17:55:15 INFO synapse.federation.sender.transaction_manager - federation_transaction_transmission_loop-0 - TX [hs-r.localhost:37051] {1679676912667} got 200 response
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - Acquiring room lock to fetch 1 missing prev_events: ['$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI']
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - Acquired room lock to fetch 1 missing prev_events
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - Requesting missing events between ['$XIUf0Jg_6IW7ScFWOsQd83kQX69w3L4Z-UAECIj-sCo'] and $spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - {POST-O-11} [hs-s.localhost:51845] Sending request: POST matrix://hs-s.localhost:51845/_matrix/federation/v1/get_missing_events/%21roomid%3Ahs-c.localhost%3A49005; timeout 60.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.access.https.51845 - POST-8 - ::1 - 51845 - Received request: POST /_matrix/federation/v1/get_missing_events/%21roomid%3Ahs-c.localhost%3A49005
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-2 - {GET-O-10} [hs-r.localhost:37051] Sending request: GET matrix://hs-r.localhost:37051/_matrix/key/v2/server; timeout 10.000000s
	hs-r.localhost:37051 17:55:15 DEBUG synapse.access.https.37051 - GET-9 - ::1 - 37051 - Received request: GET /_matrix/key/v2/server
	hs-r.localhost:37051 17:55:15 INFO synapse.access.https.37051 - GET-9 - ::1 - 37051 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-2 - {GET-O-10} [hs-r.localhost:37051] Got response headers: 200 OK
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-2 - {GET-O-10} [hs-r.localhost:37051] Completed request: 200 OK in 0.00 secs, got 323 bytes - GET matrix://hs-r.localhost:37051/_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.access.https.51845 - POST-8 - ::1 - 51845 - {hs-r.localhost:37051} Processed request: 0.011sec/0.000sec (0.000sec, 0.000sec) (0.001sec/0.001sec/5) 3278B 200 "POST /_matrix/federation/v1/get_missing_events/%21roomid%3Ahs-c.localhost%3A49005 HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - {POST-O-11} [hs-s.localhost:51845] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - {POST-O-11} [hs-s.localhost:51845] Completed request: 200 OK in 0.01 secs, got 3278 bytes - POST matrix://hs-s.localhost:51845/_matrix/federation/v1/get_missing_events/%21roomid%3Ahs-c.localhost%3A49005
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-6 - {GET-O-12} [hs-c.localhost:49005] Sending request: GET matrix://hs-c.localhost:49005/_matrix/key/v2/server; timeout 10.000000s
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.federation.matrix_federation_agent - ServerKeyFetcher-6 - Connecting to hs-c.localhost:49005
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-7 - {GET-O-13} [hs-s.localhost:51845] Sending request: GET matrix://hs-s.localhost:51845/_matrix/key/v2/server; timeout 10.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.access.https.51845 - GET-9 - ::1 - 51845 - Received request: GET /_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.access.https.51845 - GET-9 - ::1 - 51845 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-7 - {GET-O-13} [hs-s.localhost:51845] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-7 - {GET-O-13} [hs-s.localhost:51845] Completed request: 200 OK in 0.00 secs, got 323 bytes - GET matrix://hs-s.localhost:51845/_matrix/key/v2/server

hs-r -> hs-c: GET /_matrix/key/v2/server
hs-c -> hs-r:
    {
      "server_name": "hs-c.localhost:49005",
      "verify_keys": { "ed25519:1": { "key": "X4U4vyfvBTyE/Wneqgimltt+VZYspRgRWh+Yy8ONZms" } },
      "old_verify_keys": { },
      "valid_until_ts": 1679680515258,
      "signatures": { "hs-c.localhost:49005": { "ed25519:1": "vLS372z1yDXsEkzI6wV5LspbF7LIuG4whm3O1bCNCrGedANrchVyZJbrGPWeZjzZSpiOLa0VW81Af+PIR20PDA" } }
    }

logs:
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-6 - {GET-O-12} [hs-c.localhost:49005] Got response headers: 200 OK
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-6 - {GET-O-12} [hs-c.localhost:49005] Completed request: 200 OK in 0.01 secs, got 326 bytes - GET matrix://hs-c.localhost:49005/_matrix/key/v2/server
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - Got 5 prev_events
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - De-outliering event $HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - De-outliering event $5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - De-outliering event $jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - De-outliering event $lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI - Processing pulled event <FrozenEventV3 event_id=$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI, type=m.room.member, state_key=@sender:hs-s.localhost:51845, outlier=False>
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI - Event $y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI is missing prev_events ['$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I']: calculating state for a backwards extremity
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI - Requesting state after missing prev_event $lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I
	hs-r.localhost:37051 17:55:15 DEBUG synapse.http.matrixfederationclient - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI-$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I - {GET-O-14} [hs-s.localhost:51845] Sending request: GET matrix://hs-s.localhost:51845/_matrix/federation/v1/state_ids/%21roomid%3Ahs-c.localhost%3A49005?event_id=%24lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I; timeout 60.000000s
	hs-s.localhost:51845 17:55:15 DEBUG synapse.access.https.51845 - GET-10 - ::1 - 51845 - Received request: GET /_matrix/federation/v1/state_ids/%21roomid%3Ahs-c.localhost%3A49005?event_id=%24lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-3 - {GET-O-11} [hs-r.localhost:37051] Sending request: GET matrix://hs-r.localhost:37051/_matrix/key/v2/server; timeout 10.000000s
	hs-r.localhost:37051 17:55:15 DEBUG synapse.access.https.37051 - GET-10 - ::1 - 37051 - Received request: GET /_matrix/key/v2/server
	hs-r.localhost:37051 17:55:15 INFO synapse.access.https.37051 - GET-10 - ::1 - 37051 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 323B 200 "GET /_matrix/key/v2/server HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-s.localhost:51845 17:55:15 DEBUG synapse.http.matrixfederationclient - ServerKeyFetcher-3 - {GET-O-11} [hs-r.localhost:37051] Got response headers: 200 OK
	hs-s.localhost:51845 17:55:15 INFO synapse.http.matrixfederationclient - ServerKeyFetcher-3 - {GET-O-11} [hs-r.localhost:37051] Completed request: 200 OK in 0.00 secs, got 323 bytes - GET matrix://hs-r.localhost:37051/_matrix/key/v2/server
	hs-s.localhost:51845 17:55:15 INFO synapse.http.server - GET-10 - <SynapseRequest at 0x7fb08082d1d0 method='GET' uri='/_matrix/federation/v1/state_ids/%21roomid%3Ahs-c.localhost%3A49005?event_id=%24lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I' clientproto='HTTP/1.1' site='51845'> SynapseError: 404 - State not known at event $lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I
	hs-s.localhost:51845 17:55:15 INFO synapse.access.https.51845 - GET-10 - ::1 - 51845 - {hs-r.localhost:37051} Processed request: 0.009sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/1) 105B 404 "GET /_matrix/federation/v1/state_ids/%21roomid%3Ahs-c.localhost%3A49005?event_id=%24lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I HTTP/1.1" "Synapse/1.72.0" [0 dbevts]
	hs-r.localhost:37051 17:55:15 INFO synapse.http.matrixfederationclient - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI-$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I - {GET-O-14} [hs-s.localhost:51845] Got response headers: 404 Not Found
	hs-r.localhost:37051 17:55:15 WARNING synapse.http.matrixfederationclient - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI-$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I - {GET-O-14} [hs-s.localhost:51845] Request failed: GET matrix://hs-s.localhost:51845/_matrix/federation/v1/state_ids/%21roomid%3Ahs-c.localhost%3A49005?event_id=%24lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I: HttpResponseException('404: Not Found')
	hs-r.localhost:37051 17:55:15 WARNING synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI - Error attempting to resolve state at missing prev_events: 404: Not Found
	hs-r.localhost:37051 17:55:15 WARNING synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI - Pulled event $y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI failed history check.
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI - Processing pulled event <FrozenEventV3 event_id=$HhL8VDbLxXnA20bDBotKPvN5nA9g3dQVd9Z4AdLt9wI, type=m.room.create, state_key=, outlier=False>
	hs-r.localhost:37051 17:55:15 INFO synapse.state - persist_events-5 - Resolving state for !roomid:hs-c.localhost:49005 with groups [2, 4]
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU - Processing pulled event <FrozenEventV3 event_id=$5K5xj1rzu7bOXIA_Q2a2DRtnxImWW8i1pPpioD-XrFU, type=m.room.member, state_key=@creator:hs-c.localhost:49005, outlier=False>
	hs-r.localhost:37051 17:55:15 INFO synapse.state - persist_events-6 - Resolving state for !roomid:hs-c.localhost:49005 with groups [2, 5]
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc - Processing pulled event <FrozenEventV3 event_id=$jlJY1i6dkKcPD4mdyUGndklDpTWlXbCe2Wb_8y3hAYc, type=m.room.power_levels, state_key=, outlier=False>

[noise from ijson.common.IncompleteJSONError]

logs:
	hs-r.localhost:37051 17:55:15 INFO synapse.state - persist_events-7 - Resolving state for !roomid:hs-c.localhost:49005 with groups [2, 6]
	hs-r.localhost:37051 17:55:15 INFO synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A-$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I - Processing pulled event <FrozenEventV3 event_id=$lWiBmqqAmCrLeslJyrclIRArVc2aSsiQwkpeExK2U8I, type=m.room.join_rules, state_key=, outlier=False>
	hs-r.localhost:37051 17:55:15 WARNING synapse.handlers.federation_event - _process_incoming_pdus_in_room_inner-1-$spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A - Rejecting: failed to fetch 1 prev events: ['$y_IDcbtWXhZD9TLa1gBfWHUpUoUyyvnjY5pG3PzHSoI']
	hs-r.localhost:37051 17:55:15 WARNING synapse.federation.federation_server - _process_incoming_pdus_in_room_inner-1 - Error handling PDU $spB7dvLz53tx1cYeyv8GIH0uP7CVLW0urlPmtSDrj3A: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.

[noise from ijson.common.IncompleteJSONError]

and then nothing happens unless one of the clients sends a message.

Homeserver

n/a

Synapse Version

v1.74.0rc1 up to develop

Installation Method

Other (please mention below)

Database

sqlite

Workers

Single process

Platform

ran with poetry from git

Configuration

config template:

server_name: {server_name}
public_baseurl: http://{name}.localhost:{port}/
enable_registration: true
enable_registration_without_verification: true


# Configure server to listen on both $https_port and $port
# This overides some of the default settings above
listeners:
  - port: {https_port}
    type: http
    tls: true
    bind_addresses: ['::1', '127.0.0.1']
    resources:
      - names: [client, federation]
  - port: {port}
    tls: false
    bind_addresses: ['::1', '127.0.0.1']
    type: http
    x_forwarded: true
    resources:
      - names: [client, federation]
        compress: false

use_insecure_ssl_client_just_for_testing_do_not_use: true
federation_verify_certificates: false

# Set paths for the TLS certificates.
tls_certificate_path: "{directory_path}/tls.crt"
tls_private_key_path: "{directory_path}/tls.key"

# Ignore keys from the trusted keys server
trusted_key_servers: []
#   - server_name: "matrix.org"
#     accept_keys_insecurely: true

# disable presence, it's noisy
presence:
  enabled: false


# Allow the servers to communicate over localhost.
ip_range_whitelist:
- '127.0.0.1/8'
- '::1/128'

report_stats: false

log_config: "{log_config}"

Relevant log output

see above, interleaved with request dumps

Anything else that would be useful to know?

No response

[squahtx]

Is the custom homeserver something you're implementing? Can you try populating the depth field of events, so that it's at least one greater than the max depth of all prev events?

[progval]

Is the custom homeserver something you're implementing?

Yes

Can you try populating the depth field of events, so that it's at least one greater than the max depth of all prev events?

Indeed! Setting it in the make_join reply resolves the error. Merely setting it to 1 in the make_join response is enough

[squahtx]

Note that the spec says that when depth reaches 2**63 - 1, it must stop incrementing. It's expected that the bug would also happen in that case.