Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Allow room creator to send MSC2716 related events in existing room versions #10566

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
28 commits
Select commit Hold shift + click to select a range
6481502
Allow room creator to send MSC2716 related events in existing room ve…
MadLittleMods Aug 10, 2021
13d0929
Add changelog
MadLittleMods Aug 10, 2021
259303a
Stop people from trying to redact MSC2716 events in unsupported room …
MadLittleMods Aug 10, 2021
16a41dd
Populate rooms.creator column for easy lookup
MadLittleMods Aug 20, 2021
fffce99
Merge branch 'develop' into madlittlemods/room-creator-allowed-to-msc…
MadLittleMods Aug 20, 2021
aafa069
Remove and switch away from get_create_event_for_room_txn
MadLittleMods Aug 20, 2021
fedd250
Fix no create event being found because no state events persisted yet
MadLittleMods Aug 21, 2021
8a2db20
Fix and add tests for rooms creator bg update
MadLittleMods Aug 21, 2021
2b177b7
Populate rooms.creator field for easy lookup
MadLittleMods Aug 25, 2021
ee406df
Add changelog
MadLittleMods Aug 25, 2021
9f8e22b
Fix usage
MadLittleMods Aug 25, 2021
759e78c
Merge branch 'develop' into madlittlemods/room-creator-allowed-to-msc…
MadLittleMods Aug 25, 2021
71c20f7
Merge branch 'madlittlemods/populate-rooms-creator-field' into madlit…
MadLittleMods Aug 25, 2021
9b828ab
Remove extra delta already included in #10697
MadLittleMods Aug 25, 2021
3c9b5a6
Don't worry about setting creator for invite
MadLittleMods Aug 25, 2021
9a600ff
Only iterate over rows missing the creator
MadLittleMods Aug 31, 2021
79b4991
Use constant to fetch room creator field
MadLittleMods Aug 31, 2021
25db289
More protection from other random types
MadLittleMods Aug 31, 2021
41e72c2
Move new background update to end of list
MadLittleMods Aug 31, 2021
9a3c015
Fix query casing
MadLittleMods Aug 31, 2021
9a887a4
Fix ambiguity iterating over cursor instead of list
MadLittleMods Aug 31, 2021
6f9cb41
Move code not under the MSC2716 room version underneath an experiment…
MadLittleMods Aug 31, 2021
ad29e96
Add ordering to rooms creator background update
MadLittleMods Sep 1, 2021
462ab25
Add comment to better document constant
MadLittleMods Sep 1, 2021
a3581d3
Use constant field
MadLittleMods Sep 1, 2021
20196c8
Merge branch 'madlittlemods/populate-rooms-creator-field' into madlit…
MadLittleMods Sep 1, 2021
725cf22
Merge branch 'develop' into madlittlemods/room-creator-allowed-to-msc…
MadLittleMods Sep 1, 2021
e047e42
Merge branch 'develop' into madlittlemods/room-creator-allowed-to-msc…
MadLittleMods Sep 1, 2021
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/10566.feature
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Allow room creators to send historical events specified by [MSC2716](https://github.com/matrix-org/matrix-doc/pull/2716) in existing room versions.
MadLittleMods marked this conversation as resolved.
Show resolved Hide resolved
10 changes: 8 additions & 2 deletions synapse/handlers/federation_event.py
Original file line number Diff line number Diff line change
Expand Up @@ -1023,9 +1023,15 @@ async def _handle_marker_event(self, origin: str, marker_event: EventBase):
return
Copy link
Contributor Author

@MadLittleMods MadLittleMods Sep 1, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After merging develop (725cf22) (also fails on develop directly), one of the Complement tests started failing. I think it's related to some change in one of these recent refactors:

$ COMPLEMENT_ALWAYS_PRINT_SERVER_LOGS=1 COMPLEMENT_DIR=../complement ./scripts-dev/complement.sh TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event

=== RUN   TestBackfillingHistory
    msc2716_test.go:62: Deploy times: 6.225696908s blueprints, 4.390826875s containers
    client.go:370: POST hs1/_matrix/client/r0/register => 200 OK (24.494359ms)
=== RUN   TestBackfillingHistory/parallel
=== RUN   TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
=== PAUSE TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
=== CONT  TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
=== CONT  TestBackfillingHistory
    client.go:370: POST hs1/_matrix/client/r0/createRoom => 200 OK (204.314404ms)
    client.go:370: POST hs1/_matrix/client/r0/join/!pFzlAcdlcfUYBlwrgD:hs1 => 200 OK (38.364663ms)
    client.go:370: PUT hs1/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/send/m.room.message/1 => 200 OK (37.496322ms)
=== CONT  TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
    msc2716_test.go:979: SendEventSynced waiting for event ID $Mq1B-RVgu7d8QHY9cqZ4nnV5MLCHYadRVBPluTGfSXo
=== CONT  TestBackfillingHistory
    client.go:370: GET hs1/_matrix/client/r0/sync => 200 OK (40.755036ms)
    client.go:370: PUT hs1/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/send/org.matrix.msc2716.insertion/txn-m123 => 200 OK (14.01282ms)
    client.go:370: GET hs1/_matrix/client/r0/sync => 200 OK (19.589308ms)
    client.go:370: PUT hs1/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/send/m.room.message/2 => 200 OK (14.515922ms)
=== CONT  TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
    msc2716_test.go:979: SendEventSynced waiting for event ID $SrhE54fDdLcQI6dyxFE-QaTfSZhGEB0TkjUagSQ5AKc
=== CONT  TestBackfillingHistory
    client.go:370: GET hs1/_matrix/client/r0/sync => 200 OK (19.774538ms)
    client.go:370: PUT hs1/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/send/m.room.message/3 => 200 OK (15.798959ms)
=== CONT  TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
    msc2716_test.go:979: SendEventSynced waiting for event ID $CSvwLw2nHOW0O3MkI2EoTOTPqNFxI5Zdn73tzdKayBs
=== CONT  TestBackfillingHistory
    client.go:370: GET hs1/_matrix/client/r0/sync => 200 OK (18.961067ms)
    client.go:370: PUT hs1/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/send/m.room.message/4 => 200 OK (13.47559ms)
=== CONT  TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
    msc2716_test.go:979: SendEventSynced waiting for event ID $VtcB-yfsAMsd34RofKyrV9vqKLHRmuQOIlBDU3x1IDA
=== CONT  TestBackfillingHistory
    client.go:370: GET hs1/_matrix/client/r0/sync => 200 OK (18.752454ms)
    client.go:370: POST hs1/_matrix/client/unstable/org.matrix.msc2716/rooms/!pFzlAcdlcfUYBlwrgD:hs1/batch_send => 200 OK (66.974695ms)
    client.go:370: POST hs2/_matrix/client/r0/join/!pFzlAcdlcfUYBlwrgD:hs1 => 200 OK (817.637887ms)
    client.go:370: GET hs2/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/messages => 200 OK (280.548957ms)
    client.go:370: GET hs2/_matrix/client/r0/rooms/!pFzlAcdlcfUYBlwrgD:hs1/messages => 200 OK (35.166542ms)
=== CONT  TestBackfillingHistory/parallel/Historical_messages_are_visible_when_joining_on_federated_server_-_pre-made_insertion_event
    msc2716_test.go:546: MatchResponse JSONCheckOff: did not see items: [$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY] - http://localhost:55288/_matrix/client/r0/rooms/%21pFzlAcdlcfUYBlwrgD:hs1/messages?dir=b&limit=100 => {"chunk":[{"type":"m.room.member","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@charlie:hs2","content":{"membership":"join","displayname":"charlie","avatar_url":null},"state_key":"@charlie:hs2","origin_server_ts":1630527561142,"unsigned":{"age":415},"event_id":"$sy89W9Z8SIB8TahLGggY77h_FJE1LRlY47nt7ot36DM","user_id":"@charlie:hs2","age":415},{"type":"m.room.message","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@alice:hs1","content":{"body":"Message 2","msgtype":"m.text"},"origin_server_ts":1630527560337,"unsigned":{"age":977},"event_id":"$VtcB-yfsAMsd34RofKyrV9vqKLHRmuQOIlBDU3x1IDA","user_id":"@alice:hs1","age":977},{"type":"m.room.message","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@alice:hs1","content":{"body":"Message 1","msgtype":"m.text"},"origin_server_ts":1630527560303,"unsigned":{"age":1011},"event_id":"$CSvwLw2nHOW0O3MkI2EoTOTPqNFxI5Zdn73tzdKayBs","user_id":"@alice:hs1","age":1011},{"type":"m.room.message","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@alice:hs1","content":{"body":"Message 0","msgtype":"m.text"},"origin_server_ts":1630527560267,"unsigned":{"age":1047},"event_id":"$SrhE54fDdLcQI6dyxFE-QaTfSZhGEB0TkjUagSQ5AKc","user_id":"@alice:hs1","age":1047},{"type":"m.room.message","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@maria:hs1","content":{"body":"Historical 0 (chunk=0)","msgtype":"m.text","org.matrix.msc2716.historical":true},"origin_server_ts":1630527560217,"unsigned":{"age":919},"event_id":"$YgVF4lkpq3ghIZd3C0evfHSJT1mhUA3cq92-triNh6E","user_id":"@maria:hs1","age":919},{"type":"m.room.message","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@maria:hs1","content":{"body":"Historical 1 (chunk=0)","msgtype":"m.text","org.matrix.msc2716.historical":true},"origin_server_ts":1630527560218,"unsigned":{"age":915},"event_id":"$lonJkljNkygvTMCeOqLpS4YLwrKch1cyPLirnrjhmqw","user_id":"@maria:hs1","age":915},{"type":"org.matrix.msc2716.insertion","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"org.matrix.msc2716.historical":true,"org.matrix.msc2716.next_chunk_id":"mynextchunkid123"},"origin_server_ts":1630527560234,"unsigned":{"age":1080},"event_id":"$kqz1sVD1G5kyK6tZ5_UR6uLNb6dKZihbXHYi1yScmDc","user_id":"@the-bridge-user:hs1","age":1080},{"type":"org.matrix.msc2716.chunk","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"org.matrix.msc2716.chunk_id":"mynextchunkid123","org.matrix.msc2716.historical":true},"origin_server_ts":1630527560218,"unsigned":{"age":911},"event_id":"$SyQzaYC7H4vlGUrQ0YdmccOBkCg71sL0KnMn425oj1U","user_id":"@the-bridge-user:hs1","age":911},{"type":"m.room.message","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@alice:hs1","content":{"body":"Message 0","msgtype":"m.text"},"origin_server_ts":1630527560173,"unsigned":{"age":1141},"event_id":"$Mq1B-RVgu7d8QHY9cqZ4nnV5MLCHYadRVBPluTGfSXo","user_id":"@alice:hs1","age":1141},{"type":"m.room.member","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@alice:hs1","content":{"membership":"join","displayname":"alice"},"state_key":"@alice:hs1","origin_server_ts":1630527560136,"unsigned":{"age":1045},"event_id":"$InXEtqdkYCAkjYvcYb_JctayzOP_1l_JIUvMSuwoHVs","user_id":"@alice:hs1","age":1045},{"type":"m.room.name","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"name":"the hangout spot"},"state_key":"","origin_server_ts":1630527560093,"unsigned":{"age":1088},"event_id":"$-OR4lb5yd1mjKROL4_fQXcp5tdVPdepJ0a0Jh0_xilU","user_id":"@the-bridge-user:hs1","age":1088},{"type":"m.room.history_visibility","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"history_visibility":"shared"},"state_key":"","origin_server_ts":1630527560063,"unsigned":{"age":1118},"event_id":"$d6nTx76gH2FrLTYfuWDGmTORvUaFciDanehIqWWLZYU","user_id":"@the-bridge-user:hs1","age":1118},{"type":"m.room.join_rules","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"join_rule":"public"},"state_key":"","origin_server_ts":1630527560039,"unsigned":{"age":1142},"event_id":"$QXoHXXLkWxVAlJ_BCiQwQnd3ypt9498g6oBizto5Bnk","user_id":"@the-bridge-user:hs1","age":1142},{"type":"m.room.power_levels","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"users":{"@the-bridge-user:hs1":100},"users_default":0,"events":{"m.room.name":50,"m.room.power_levels":100,"m.room.history_visibility":100,"m.room.canonical_alias":50,"m.room.avatar":50,"m.room.tombstone":100,"m.room.server_acl":100,"m.room.encryption":100},"events_default":0,"state_default":50,"ban":50,"kick":50,"redact":50,"invite":50,"historical":100},"state_key":"","origin_server_ts":1630527560009,"unsigned":{"age":1172},"event_id":"$bE3VMr1GJkI5BtRC6U1ycsOSwq0AyzAj8fMSm6q4HhQ","user_id":"@the-bridge-user:hs1","age":1172},{"type":"m.room.member","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"membership":"join"},"state_key":"@the-bridge-user:hs1","origin_server_ts":1630527559975,"unsigned":{"age":1206},"event_id":"$Y3XQmsUTwHPz68O9whnYVObrbQkJJuHd3jcRwpWbles","user_id":"@the-bridge-user:hs1","age":1206},{"type":"m.room.create","room_id":"!pFzlAcdlcfUYBlwrgD:hs1","sender":"@the-bridge-user:hs1","content":{"room_version":"org.matrix.msc2716","creator":"@the-bridge-user:hs1"},"state_key":"","origin_server_ts":1630527559920,"unsigned":{"age":1261},"event_id":"$uCV9s7uW1xlENfEBPcZ2hivKsqexyGKS3XDBUcOb84k","user_id":"@the-bridge-user:hs1","age":1261}],"start":"s15_0_0_0_0_0_0_0_0","end":"t1-1_0_0_0_0_0_0_0_0"}
2021/09/01 15:19:21 ============================================

2021/09/01 15:19:21 23133d0dbb53beb67b9d22502e16679ceca3dee79b6ded980cbeafba7730900e : Server logs:
Signature ok
subject=CN = hs2
[...]


2021-09-01 20:19:21,462 - synapse.handlers.federation_event - 746 - WARNING - GET-4-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation_event.py", line 711, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation_event.py", line 777, in _get_state_after_missing_prev_event
    ) = await self.federation_client.get_room_state_ids(
  File "/usr/local/lib/python3.8/site-packages/synapse/federation/federation_client.py", line 370, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/usr/local/lib/python3.8/site-packages/synapse/federation/transport/client.py", line 71, in get_room_state_ids
    return await self.client.get_json(
  File "/usr/local/lib/python3.8/site-packages/synapse/http/matrixfederationclient.py", line 1001, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/usr/local/lib/python3.8/site-packages/synapse/http/matrixfederationclient.py", line 385, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/usr/local/lib/python3.8/site-packages/synapse/http/matrixfederationclient.py", line 631, in _send_request
    raise exc
synapse.api.errors.HttpResponseException: 404: Not Found
2021-09-01 20:19:21,464 - synapse.handlers.federation_event - 637 - WARNING - GET-4-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Pulled event $hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY failed history check.
2021-09-01 20:19:21,465 - synapse.handlers.federation_event - 605 - INFO - GET-4-$lonJkljNkygvTMCeOqLpS4YLwrKch1cyPLirnrjhmqw - Processing pulled event <FrozenEventV3 event_id='$lonJkljNkygvTMCeOqLpS4YLwrKch1cyPLirnrjhmqw', type='m.room.message', state_key=None>
2021-09-01 20:19:21,472 - synapse.handlers.federation_event - 605 - INFO - GET-4-$kqz1sVD1G5kyK6tZ5_UR6uLNb6dKZihbXHYi1yScmDc - Processing pulled event <FrozenEventV3 event_id='$kqz1sVD1G5kyK6tZ5_UR6uLNb6dKZihbXHYi1yScmDc', type='org.matrix.msc2716.insertion', state_key=None>
2021-09-01 20:19:21,479 - synapse.handlers.federation_event - 605 - INFO - GET-4-$SyQzaYC7H4vlGUrQ0YdmccOBkCg71sL0KnMn425oj1U - Processing pulled event <FrozenEventV3 event_id='$SyQzaYC7H4vlGUrQ0YdmccOBkCg71sL0KnMn425oj1U', type='org.matrix.msc2716.chunk', state_key=None>
2021-09-01 20:19:21,481 - synapse.handlers.federation_event - 1567 - INFO - GET-4-$SyQzaYC7H4vlGUrQ0YdmccOBkCg71sL0KnMn425oj1U - auth_events refers to events which are not in our calculated auth chain: {'$Y3XQmsUTwHPz68O9whnYVObrbQkJJuHd3jcRwpWbles'}
2021-09-01 20:19:21,481 - synapse.state - 461 - INFO - GET-4-$SyQzaYC7H4vlGUrQ0YdmccOBkCg71sL0KnMn425oj1U - Resolving state for !pFzlAcdlcfUYBlwrgD:hs1 with 2 groups
2021-09-01 20:19:21,482 - synapse.handlers.federation_event - 1606 - INFO - GET-4-$SyQzaYC7H4vlGUrQ0YdmccOBkCg71sL0KnMn425oj1U - After state res: updating auth_events with new state {('m.room.member', '@the-bridge-user:hs1'): '$Y3XQmsUTwHPz68O9whnYVObrbQkJJuHd3jcRwpWbles'}
2021-09-01 20:19:21,489 - synapse.handlers.federation_event - 605 - INFO - GET-4-$SrhE54fDdLcQI6dyxFE-QaTfSZhGEB0TkjUagSQ5AKc - Processing pulled event <FrozenEventV3 event_id='$SrhE54fDdLcQI6dyxFE-QaTfSZhGEB0TkjUagSQ5AKc', type='m.room.message', state_key=None>
2021-09-01 20:19:21,496 - synapse.handlers.federation_event - 605 - INFO - GET-4-$CSvwLw2nHOW0O3MkI2EoTOTPqNFxI5Zdn73tzdKayBs - Processing pulled event <FrozenEventV3 event_id='$CSvwLw2nHOW0O3MkI2EoTOTPqNFxI5Zdn73tzdKayBs', type='m.room.message', state_key=None>
2021-09-01 20:19:21,501 - synapse.handlers.federation_event - 605 - INFO - GET-4-$VtcB-yfsAMsd34RofKyrV9vqKLHRmuQOIlBDU3x1IDA - Processing pulled event <FrozenEventV3 event_id='$VtcB-yfsAMsd34RofKyrV9vqKLHRmuQOIlBDU3x1IDA', type='m.room.message', state_key=None>
2021-09-01 20:19:21,531 - synapse.access.http.8008 - 389 - INFO - GET-4 - ::ffff:192.168.112.1 - 8008 - {@charlie:hs2} Processed request: 0.275sec/-0.000sec (0.041sec, 0.009sec) (0.219sec/0.045sec/91) 5474B 200 "GET /_matrix/client/r0/rooms/%21pFzlAcdlcfUYBlwrgD:hs1/messages?dir=b&limit=100 HTTP/1.1" "Go-http-client/1.1" [16 dbevts]
2021-09-01 20:19:21,548 - synapse.http.matrixfederationclient - 287 - INFO - GET-5 - {GET-O-10} [hs1] Completed request: 200 OK in 0.01 secs, got 774 bytes - GET matrix://hs1/_matrix/federation/v1/backfill/%21pFzlAcdlcfUYBlwrgD%3Ahs1?v=%24hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY&limit=100
2021-09-01 20:19:21,550 - synapse.handlers.federation_event - 605 - INFO - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Processing pulled event <FrozenEventV3 event_id='$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY', type='org.matrix.msc2716.insertion', state_key=None>
2021-09-01 20:19:21,550 - synapse.handlers.federation_event - 622 - INFO - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - De-outliering event $hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY
2021-09-01 20:19:21,552 - synapse.handlers.federation_event - 683 - INFO - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Event $hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY is missing prev_events ['$TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg']: calculating state for a backwards extremity
2021-09-01 20:19:21,552 - synapse.handlers.federation_event - 705 - INFO - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Requesting state after missing prev_event $TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg
2021-09-01 20:19:21,559 - synapse.http.matrixfederationclient - 592 - INFO - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY-$TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg - {GET-O-11} [hs1] Got response headers: 404 Not Found
2021-09-01 20:19:21,559 - synapse.http.matrixfederationclient - 670 - WARNING - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY-$TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg - {GET-O-11} [hs1] Request failed: GET matrix://hs1/_matrix/federation/v1/state_ids/%21pFzlAcdlcfUYBlwrgD%3Ahs1?event_id=%24TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg: HttpResponseException('404: Not Found')
2021-09-01 20:19:21,560 - synapse.handlers.federation_event - 746 - WARNING - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Error attempting to resolve state at missing prev_events
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation_event.py", line 711, in _resolve_state_at_missing_prevs
    remote_state = await self._get_state_after_missing_prev_event(
  File "/usr/local/lib/python3.8/site-packages/synapse/handlers/federation_event.py", line 777, in _get_state_after_missing_prev_event
    ) = await self.federation_client.get_room_state_ids(
  File "/usr/local/lib/python3.8/site-packages/synapse/federation/federation_client.py", line 370, in get_room_state_ids
    result = await self.transport_layer.get_room_state_ids(
  File "/usr/local/lib/python3.8/site-packages/synapse/federation/transport/client.py", line 71, in get_room_state_ids
    return await self.client.get_json(
  File "/usr/local/lib/python3.8/site-packages/synapse/http/matrixfederationclient.py", line 1001, in get_json
    response = await self._send_request_with_optional_trailing_slash(
  File "/usr/local/lib/python3.8/site-packages/synapse/http/matrixfederationclient.py", line 385, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/usr/local/lib/python3.8/site-packages/synapse/http/matrixfederationclient.py", line 631, in _send_request
    raise exc
synapse.api.errors.HttpResponseException: 404: Not Found
2021-09-01 20:19:21,560 - synapse.handlers.federation_event - 637 - WARNING - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Pulled event $hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY failed history check.
2021-09-01 20:19:21,567 - synapse.access.http.8008 - 389 - INFO - GET-5 - ::ffff:192.168.112.1 - 8008 - {@charlie:hs2} Processed request: 0.033sec/-0.000sec (0.009sec, 0.000sec) (0.003sec/0.001sec/7) 5474B 200 "GET /_matrix/client/r0/rooms/%21pFzlAcdlcfUYBlwrgD:hs1/messages?dir=b&limit=100 HTTP/1.1" "Go-http-client/1.1" [0 dbevts]
2021/09/01 15:19:21 ============== 23133d0dbb53beb67b9d22502e16679ceca3dee79b6ded980cbeafba7730900e : END LOGS ==============

Copy link
Contributor Author

@MadLittleMods MadLittleMods Sep 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems like our fake prev_event is coming back to bite us 😣 and is causing the insertion event that references the fake event to be rejected. The fake event does appear to still play nicely with the state though (maybe so far AFAICT).

  • $hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY is the insertion event for the chunk
  • $TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg is the fake event
Event $hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY is missing prev_events ['$TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg']: calculating state for a backwards extremity
Requesting state after missing prev_event $TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg
WARNING - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY-$TiICyIaUJplRPSUJfVCHnjmtOmYtRFiwoWWnYvLIABg - {GET-O-14} [hs1] Request failed: GET matrix://hs1/_matrix/federation/v1/state_ids/%21yOGzjYcqVcKjTRlAxz%3Ahs1?event_id=%24tJUTwqLgFBCygrtCiMInLChmRCqNFdnbHdqaEbCaVnF: HttpResponseException('404: Not Found')
WARNING - GET-5-$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY - Error attempting to resolve state at missing prev_events
FederationError=ERROR 403: We can't get valid state history. event_id=$hbHXgulNKlmg9mkGQiBH5SSgq2NL4GO70sIIfHCa-YY

We originally discussed the fake event at matrix-org/matrix-spec-proposals#2716 (comment) (look for the floating discussion) to make the state events float off on their own pretending it was in the depths of history somewhere we haven't fetched yet.

And the fake event is used as a prev_event for the insertion event because,

# All but the first base insertion event should point at a fake
# event, which causes the HS to ask for the state at the start of
# the chunk later.
prev_event_ids = [fake_prev_event_id]

and was changed in #10245 (specifically a8c5311) for federation. But previously they were always connected to the prev event specified in the query param. This change was made as discussed at:

I think all but the first insertion event should point at a fake event, which causes the HS to ask for the state at the start of the chunk?

-- @erikjohnston, https://matrix.to/#/!UytJQHLQYfvYWsGrGY:jki.re/$12bTUiObDFdHLAYtT7E-BvYRp3k_xv8w0dUQHibasJk?via=jki.re&via=matrix.org

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like the culprit is in #10645 which changed how backfill gets state and auths events.

If I restore _get_state_for_room and the old implementation in backfill, the Complement tests pass again.

Copy link
Contributor Author

@MadLittleMods MadLittleMods Sep 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hmmm, maaayyybe we don't need to "[cause] the HS to ask for the state at the start of the chunk later." using fake_prev_event_id with the insertion events. The Complement tests still pass if I revert a8c5311.

And to jog the memory, here is the DAG in either scenario (pulled from the description history in #10245):

Connected to main DAG prev_event With fake_prev_event_id

@erikjohnston I could use some insight here ^ in case you have opinions on keeping the fake event or where/what we need to add to accommodate it if we need to use it still.

Otherwise, I will be digging into the past and new backfill implementation finding the key difference.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@erikjohnston I could use some insight here ^ in case you have opinions on keeping the fake event or where/what we need to add to accommodate it if we need to use it still.

If we don't have the fake event then the state of the chunks will be inherited from A, which will likely be wrong, so I think we still need the prev event.


It looks like that PR changed the way we handle fetching state for backfills, before we'd just get the state at the last event, whereas now we try and get the state for each prev event (including the fake event), which obviously fails. I'll talk to @richvdh to try and see what the correct thing to do here is, but my hunch is we probably do want to be able to handle the case where no one has the state for an event.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I chatted with @richvdh briefly, and the conclusion was that a) that code is protecting against an attack where a remote server could arbitrarily replace the servers view of the current state of the room, but b) the mitigation we use is a sledgehammer and we should replace it with something more intelligent that both mitigates the attack and gracefully handles missing events.

I'm not sure what that looks like yet, but will have a think.

Copy link
Contributor Author

@MadLittleMods MadLittleMods Sep 3, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the checking this out! Since the Complement test also fails on develop, I think we're good to merge this and move forward.

I'll create a new separate issue to track this new unobtanium fake event hammer we're going to forge 💪

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tracked in #10764


# Skip processing a marker event if the room version doesn't
# support it.
# support it or the event is not from the room creator.
room_version = await self.store.get_room_version(marker_event.room_id)
if not room_version.msc2716_historical:
create_event = await self.store.get_create_event_for_room(marker_event.room_id)
room_creator = create_event.content.get(EventContentFields.ROOM_CREATOR)
Comment on lines +1028 to +1029
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@MadLittleMods sorry to raise this PR from the dead, but can you remember if there is a reason we use room_creator = create_event.content.get(EventContentFields.ROOM_CREATOR) here, but select the creator column from rooms elsewhere in the same PR?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Probably an oversight. I can't think of a reason why it would matter. We just want the room creator which doesn't change.

For the insertion and batch events, we switched from the m.room.create event lookup and moved to the rooms table lookup in aafa069

@richvdh Are you touching this in a different refactor to update this?

if (
not room_version.msc2716_historical
or not self.hs.config.experimental.msc2716_enabled
or marker_event.sender != room_creator
):
return

logger.debug("_handle_marker_event: received %s", marker_event)
Expand Down
28 changes: 25 additions & 3 deletions synapse/handlers/message.py
Original file line number Diff line number Diff line change
Expand Up @@ -1393,6 +1393,9 @@ async def persist_and_notify_client_event(
allow_none=True,
)

room_version = await self.store.get_room_version_id(event.room_id)
room_version_obj = KNOWN_ROOM_VERSIONS[room_version]

# we can make some additional checks now if we have the original event.
if original_event:
if original_event.type == EventTypes.Create:
Expand All @@ -1404,16 +1407,35 @@ async def persist_and_notify_client_event(
if original_event.type == EventTypes.ServerACL:
raise AuthError(403, "Redacting server ACL events is not permitted")

# Add a little safety stop-gap to prevent people from trying to
# redact MSC2716 related events when they're in a room version
# which does not support it yet. We allow people to use MSC2716
# events in existing room versions but only from the room
# creator since it does not require any changes to the auth
# rules and in effect, the redaction algorithm . In the
# supported room version, we add the `historical` power level to
# auth the MSC2716 related events and adjust the redaction
# algorthim to keep the `historical` field around (redacting an
# event should only strip fields which don't affect the
# structural protocol level).
is_msc2716_event = (
original_event.type == EventTypes.MSC2716_INSERTION
or original_event.type == EventTypes.MSC2716_CHUNK
or original_event.type == EventTypes.MSC2716_MARKER
)
if not room_version_obj.msc2716_historical and is_msc2716_event:
raise AuthError(
403,
"Redacting MSC2716 events is not supported in this room version",
)

prev_state_ids = await context.get_prev_state_ids()
auth_events_ids = self._event_auth_handler.compute_auth_events(
event, prev_state_ids, for_verification=True
)
auth_events_map = await self.store.get_events(auth_events_ids)
auth_events = {(e.type, e.state_key): e for e in auth_events_map.values()}

room_version = await self.store.get_room_version_id(event.room_id)
room_version_obj = KNOWN_ROOM_VERSIONS[room_version]

if event_auth.check_redaction(
room_version_obj, event, auth_events=auth_events
):
Expand Down
32 changes: 27 additions & 5 deletions synapse/storage/databases/main/events.py
Original file line number Diff line number Diff line change
Expand Up @@ -1770,10 +1770,21 @@ def _handle_insertion_event(self, txn: LoggingTransaction, event: EventBase):
# Not a insertion event
return

# Skip processing a insertion event if the room version doesn't
# support it.
# Skip processing an insertion event if the room version doesn't
# support it or the event is not from the room creator.
room_version = self.store.get_room_version_txn(txn, event.room_id)
if not room_version.msc2716_historical:
room_creator = self.db_pool.simple_select_one_onecol_txn(
txn,
table="rooms",
keyvalues={"room_id": event.room_id},
retcol="creator",
allow_none=True,
)
if (
not room_version.msc2716_historical
or not self.hs.config.experimental.msc2716_enabled
MadLittleMods marked this conversation as resolved.
Show resolved Hide resolved
or event.sender != room_creator
):
return

next_chunk_id = event.content.get(EventContentFields.MSC2716_NEXT_CHUNK_ID)
Expand Down Expand Up @@ -1822,9 +1833,20 @@ def _handle_chunk_event(self, txn: LoggingTransaction, event: EventBase):
return

# Skip processing a chunk event if the room version doesn't
# support it.
# support it or the event is not from the room creator.
room_version = self.store.get_room_version_txn(txn, event.room_id)
if not room_version.msc2716_historical:
room_creator = self.db_pool.simple_select_one_onecol_txn(
txn,
table="rooms",
keyvalues={"room_id": event.room_id},
retcol="creator",
allow_none=True,
)
if (
not room_version.msc2716_historical
or not self.hs.config.experimental.msc2716_enabled
or event.sender != room_creator
):
return

chunk_id = event.content.get(EventContentFields.MSC2716_CHUNK_ID)
Expand Down