Suspected flake: Room state after a rejected message event is the same as before

[squahtx]

https://github.com/matrix-org/synapse/runs/7302527446?check_suite_focus=true

The test sends an event that is expected to be rejected, followed by a good event over federation.
The test then waits for the good event to come down sync, which timed out.

# Started: 2022-07-12 13:34:27.622
# Ended: 2022-07-12 13:34:38.585
# Timed out waiting for test at /sytest/run-tests.pl line 864.
# 0.092001: Registered new user @anon-20220712_132036-816:localhost:8840
# 0.957852: Joined room 1: !oqQHUzyCyulokYHZWj:localhost:8840
# 0.958717: sending rejected event $Oid0DugUWNUORqfMeqwWqaBc3FwE3Q1RelKC_uQPlss
# {
#   auth_events      => [
#                         "\$cYvd1YxzRwvjghbXgduL03Rejx_qIwm04ko3CJnKanI",
#                         "\$qALDoPCc5-XzW2XA2uBsw1dZ0pr_XvBIXuN8OtgDOYo",
#                       ],
#   content          => { body => "Rejected" },
#   depth            => JSON::number(8),
#   hashes           => { sha256 => "VYUYWEFtsRm9CImMj0znhmWpBH+Sn8uoa2gDiTq5HSE" },
#   origin           => "localhost:35555",
#   origin_server_ts => JSON::number(1657632868580),
#   prev_events      => ["\$XhVEnNK9Tx5Kd0prYfwI6JuZtp1lI2UU4a8Y9AwTMmg"],
#   room_id          => "!oqQHUzyCyulokYHZWj:localhost:8840",
#   sender           => "\@fake_sender:localhost:35555",
#   signatures       => {
#                         "localhost:35555" => {
#                           "ed25519:1" => "FYjfmQqZd1qx/X3MYZDrV4sFdCoqp//HCDpqojyJtTIxGkguqe3FtCOC7YVlfpfNR+2J/RZW5fC2eQpOQTFdDg",
#                         },
#                       },
#   type             => "m.room.message",
# }
# 0.976724: sending regular event $N8EeaOM8uRNmYsSa9z6dW3FD[10](https://github.com/matrix-org/synapse/runs/7302527446?check_suite_focus=true#step:6:11)610PCB9NfCRnrAGa8
# {
#   auth_events      => [
#                         "\$cYvd1YxzRwvjghbXgduL03Rejx_qIwm04ko3CJnKanI",
#                         "\$qALDoPCc5-XzW2XA2uBsw1dZ0pr_XvBIXuN8OtgDOYo",
#                         "\$XhVEnNK9Tx5Kd0prYfwI6JuZtp1lI2UU4a8Y9AwTMmg",
#                       ],
#   content          => { body => "Hello" },
#   depth            => JSON::number(9),
#   hashes           => { sha256 => "9/CET+l84CmY1EKDTmMQKYKezG4RaSaT822ewvljsVY" },
#   origin           => "localhost:35555",
#   origin_server_ts => JSON::number(1657632868581),
#   prev_events      => ["\$Oid0DugUWNUORqfMeqwWqaBc3FwE3Q1RelKC_uQPlss"],
#   room_id          => "!oqQHUzyCyulokYHZWj:localhost:8840",
#   sender           => "\@__ANON__-57:localhost:35555",
#   signatures       => {
#                         "localhost:35555" => {
#                           "ed25519:1" => "KUY7lkDVsIEX9+8BYnVQ5qLxb8W+d7gGo8sesUIM103P7vFeJwDt/IUWk2b8ZypZgAqgSd4csiQo8OQHSds5BA",
#                         },
#                       },
#   type             => "m.room.message",
# }
# 1.021327

federation_reader.log:

2022-07-12 13:34:28,406 - synapse.access.http.8808 - 471 - INFO - GET-448 - 127.0.0.1 - 8808 - {localhost:35555} Processed request: 0.026sec/0.001sec (0.008sec, 0.002sec) (0.003sec/0.009sec/12) 520B 200 "GET /_matrix/federation/v1/make_join/!oqQHUzyCyulokYHZWj:localhost:8840/@__ANON__-57:localhost:35555?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=7&ver=8&ver=9 HTTP/1.1" "Perl + Net::Async::HTTP/0.48" [3 dbevts]

2022-07-12 13:34:28,597 - synapse.federation.federation_server - 1155 - INFO - _process_incoming_pdus_in_room_inner-45 - handling received PDU in room !oqQHUzyCyulokYHZWj:localhost:8840: <FrozenEventV3 event_id=$Oid0DugUWNUORqfMeqwWqaBc3FwE3Q1RelKC_uQPlss, type=m.room.message, state_key=None, outlier=False>
2022-07-12 13:34:28,610 - synapse.handlers.federation_event - 1549 - WARNING - _process_incoming_pdus_in_room_inner-45-$Oid0DugUWNUORqfMeqwWqaBc3FwE3Q1RelKC_uQPlss - While checking auth of <FrozenEventV3 event_id=$Oid0DugUWNUORqfMeqwWqaBc3FwE3Q1RelKC_uQPlss, type=m.room.message, state_key=None, outlier=False> against auth_events: 403: User @fake_sender:localhost:35555 not in room !oqQHUzyCyulokYHZWj:localhost:8840 (None)
2022-07-12 13:34:28,624 - synapse.http.client - 450 - INFO - _process_incoming_pdus_in_room_inner-45-$Oid0DugUWNUORqfMeqwWqaBc3FwE3Q1RelKC_uQPlss - Received response to POST http://localhost:8830/_synapse/replication/fed_send_events/dmnkAsVFVb: 200

2022-07-12 13:35:06,778 - synapse.federation.federation_server - 185 - INFO - _handle_old_staged_events-13 - Handling old staged inbound events in !oqQHUzyCyulokYHZWj:localhost:8840
2022-07-12 13:35:06,785 - synapse.federation.federation_server - 1155 - INFO - _process_incoming_pdus_in_room_inner-61 - handling received PDU in room !oqQHUzyCyulokYHZWj:localhost:8840: <FrozenEventV3 event_id=$N8EeaOM8uRNmYsSa9z6dW3FD10610PCB9NfCRnrAGa8, type=m.room.message, state_key=None, outlier=False>

From federation_reader.log, we can see that the rejected event was processed reasonably quickly, while the good event got stuck in the staged events queue. That means that:

• the _process_incoming_pdus_in_room_inner run for the rejected event released the federation_inbound_pdu lock, then saw no staged events to process
• and Synapse failed to acquire the federation_inbound_pdu lock after queuing the good event in the staged events table.

which seems contradictory