Suspected flake: Room state after a rejected message event is the same as before #1273
Open
Description
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_innerrun for the rejected event released thefederation_inbound_pdulock, then saw no staged events to process - and Synapse failed to acquire the
federation_inbound_pdulock after queuing the good event in the staged events table.
which seems contradictory