search

matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://matrix-org.github.io/synapse
Apache License 2.0
11.79k stars 2.13k forks source link

Own member event is duplicated in timeline when joining a room #9768

Open bwindels opened 3 years ago

bwindels commented 3 years ago

When accepting an invite to a new DM, I consistently (on matrix.org) see the last two events of the timeline being my own member event, duplicated. The request URL for this is https://matrix.org/_matrix/client/r0/sync?since=m1932336751~1.1932336915_757284961_312592_815559230_699804110_2214631_242549737_904922611_187106&timeout=30000&filter=2&_cacheBuster=1532609541718558

{
  "events": [
    {
      "content": {
        "displayname": "bruno5",
        "membership": "join"
      },
      "origin_server_ts": 1617890563769,
      "sender": "@bruno5:matrix.org",
      "state_key": "@bruno5:matrix.org",
      "type": "m.room.member",
      "unsigned": {
        "age": 93068
      },
      "event_id": "$jcf51330L2Ej9-mcccs6bl5G4fdkB91xKgIkn7vOUe4"
    },
    {
      "content": {
        "ban": 50,
        "events": {
          "m.room.avatar": 50,
          "m.room.canonical_alias": 50,
          "m.room.encryption": 100,
          "m.room.history_visibility": 100,
          "m.room.name": 50,
          "m.room.power_levels": 100,
          "m.room.server_acl": 100,
          "m.room.tombstone": 100
        },
        "events_default": 0,
        "invite": 0,
        "kick": 50,
        "redact": 50,
        "state_default": 50,
        "users": {
          "@bruno4:matrix.org": 100,
          "@bruno5:matrix.org": 100
        },
        "users_default": 0
      },
      "origin_server_ts": 1617890563855,
      "sender": "@bruno5:matrix.org",
      "state_key": "",
      "type": "m.room.power_levels",
      "unsigned": {
        "age": 92982
      },
      "event_id": "$sUotYNlUwJH1r4gskhgpeDzRnmaitJ4K0f1RPh5mobk"
    },
    {
      "content": {
        "join_rule": "invite"
      },
      "origin_server_ts": 1617890563926,
      "sender": "@bruno5:matrix.org",
      "state_key": "",
      "type": "m.room.join_rules",
      "unsigned": {
        "age": 92911
      },
      "event_id": "$n5CR2u0GTgCJmpcjKIWegxjyTVKqRytjchxe_sgIsWU"
    },
    {
      "content": {
        "history_visibility": "shared"
      },
      "origin_server_ts": 1617890564015,
      "sender": "@bruno5:matrix.org",
      "state_key": "",
      "type": "m.room.history_visibility",
      "unsigned": {
        "age": 92822
      },
      "event_id": "$wFSynF9jBu54-POGzwhsrVS562kHkao6fL6fY2DCEHM"
    },
    {
      "content": {
        "guest_access": "can_join"
      },
      "origin_server_ts": 1617890564101,
      "sender": "@bruno5:matrix.org",
      "state_key": "",
      "type": "m.room.guest_access",
      "unsigned": {
        "age": 92736
      },
      "event_id": "$EFiR8kBA8K8CZuKcwSVG7E15TttlJLdCf5ulVaLNF5Q"
    },
    {
      "content": {
        "algorithm": "m.megolm.v1.aes-sha2"
      },
      "origin_server_ts": 1617890564186,
      "sender": "@bruno5:matrix.org",
      "state_key": "",
      "type": "m.room.encryption",
      "unsigned": {
        "age": 92651
      },
      "event_id": "$ns1-TrtI8Vm4b7Gtw-rfPTJZc2ZTSPzKtYoJA62_LFA"
    },
    {
      "content": {
        "avatar_url": "mxc://matrix.org/AbaQoXqdDHmFzEpEIYBXSTEP",
        "displayname": "Bruno the bloodhound",
        "is_direct": true,
        "membership": "invite"
      },
      "origin_server_ts": 1617890564287,
      "sender": "@bruno5:matrix.org",
      "state_key": "@bruno4:matrix.org",
      "type": "m.room.member",
      "unsigned": {
        "age": 92550
      },
      "event_id": "$oORFPM76LlRaBAnaNxa-K8f_Ut67paUFKcmpz-9o51w"
    },
    {
      "content": {
        "algorithm": "m.megolm.v1.aes-sha2",
        "ciphertext": "AwgAEoABSOmkHREfvz5cGZqDTvT8cYeTVrTtX+7HQ1xoMH4BCkZlsDLbXXpa1OzzL9bomP8J5EdD9sZVsR7It48CBM3VbIJfyMMBMEq5uSFIkjUyfuZPid57VuZHuNQd93Du8/wxOqUxMar+1rWu3wGXNfT43LlL5TEA2HpTm1JRr01Xu+XF666EE91s4sqZkTPWhtmQVpbSAla1QLrPrKddwN89G/TKXjrb171qGsqdu170U48PIuKBoyBRuVd/XOsoADRFEFlCvSUG8Ac",
        "device_id": "NWYSNKCJJL",
        "sender_key": "//RkE4avb7fo+VCmbK6HDa7Y4p2sPsMGCyO8/DnAyAU",
        "session_id": "JOVjdHpxd34Cm+zp4DVHhSR8UMetkWYB9olMK2rfovA"
      },
      "origin_server_ts": 1617890576653,
      "sender": "@bruno5:matrix.org",
      "type": "m.room.encrypted",
      "unsigned": {
        "age": 80184
      },
      "event_id": "$ZS3NguTnTHAq0fkIOqutai4Mbfe-MYfQqb1S5tgOK-U"
    },
    {
      "content": {
        "avatar_url": "mxc://matrix.org/AbaQoXqdDHmFzEpEIYBXSTEP",
        "displayname": "Bruno the bloodhound",
        "membership": "join"
      },
      "origin_server_ts": 1617890656548,
      "sender": "@bruno4:matrix.org",
      "state_key": "@bruno4:matrix.org",
      "type": "m.room.member",
      "unsigned": {
        "replaces_state": "$oORFPM76LlRaBAnaNxa-K8f_Ut67paUFKcmpz-9o51w",
        "prev_content": {
          "avatar_url": "mxc://matrix.org/AbaQoXqdDHmFzEpEIYBXSTEP",
          "displayname": "Bruno the bloodhound",
          "is_direct": true,
          "membership": "invite"
        },
        "prev_sender": "@bruno5:matrix.org",
        "age": 289
      },
      "event_id": "$Qwq0X0QqTvj4ANh0XZtK4okxne4D9E024wz36MtzgF4"
    },
    {
      "content": {
        "avatar_url": "mxc://matrix.org/AbaQoXqdDHmFzEpEIYBXSTEP",
        "displayname": "Bruno the bloodhound",
        "membership": "join"
      },
      "origin_server_ts": 1617890656548,
      "sender": "@bruno4:matrix.org",
      "state_key": "@bruno4:matrix.org",
      "type": "m.room.member",
      "unsigned": {
        "replaces_state": "$oORFPM76LlRaBAnaNxa-K8f_Ut67paUFKcmpz-9o51w",
        "prev_content": {
          "avatar_url": "mxc://matrix.org/AbaQoXqdDHmFzEpEIYBXSTEP",
          "displayname": "Bruno the bloodhound",
          "is_direct": true,
          "membership": "invite"
        },
        "prev_sender": "@bruno5:matrix.org",
        "age": 289
      },
      "event_id": "$Qwq0X0QqTvj4ANh0XZtK4okxne4D9E024wz36MtzgF4"
    }
  ],
  "prev_batch": "t2-1932333599_757284961_312982_815559432_699804383_2214631_242549800_904923309_187106",
  "limited": true
}
richvdh commented 3 years ago

suspect this has the same cause as https://github.com/matrix-org/synapse/issues/1995

anoadragon453 commented 3 years ago

This happens in this bit of code, where loaded_recents already contains your join membership event. recents is a list containing it as well. When loaded_recents is extended with recents, you end up with the same event in the list twice.

https://github.com/matrix-org/synapse/blob/2ca4e349e9d0c606d802ae15c06089080fa4f27e/synapse/handlers/sync.py#L523-L529

current_state_ids includes the join membership as well. Thus passing it in to filter_events_for_client via alyways_include_ids guarantees that you'll end up with that membership in loaded_recents.

I'm not sure whether recents should contain your membership, or if loaded_recents is expected not to. The event is inserted into recents when recents is created here:

https://github.com/matrix-org/synapse/blob/2ca4e349e9d0c606d802ae15c06089080fa4f27e/synapse/handlers/sync.py#L448-L451

Which only runs because potential_recents contains that same event. FYI limited is set to True, and block_all_timeline is False.

Just in case I tested with lazy-loading disabled and still found the same issue.

One hacky fix would just be to these things sets.

DMRobertson commented 2 years ago

I tried to reproduce this with a complement test. This failed. I can reproduce it on matrix.org, however. I suspect that this doesn't show up if you're running Synapse as a monolith.

DMRobertson commented 2 years ago

I tried to reproduce this with a complement test. This failed. I can reproduce it on matrix.org, however. I suspect that this doesn't show up if you're running Synapse as a monolith.

This was incorrect. I can reproduce it in complement, but only when I do a sync with a since parameter provided. I suspect there's some difference between these two code paths:

https://github.com/matrix-org/synapse/blob/a19d01c3d95f5dbd3a4bb181cb70dacd44135a8b/synapse/handlers/sync.py#L1517-L1527

DMRobertson commented 2 years ago

From printf debugging, it looks like _load_filtered_recents returns a TimelineBatch with the duplicate event.

DMRobertson commented 2 years ago

I've narrowed it down to here:

https://github.com/matrix-org/synapse/blob/a19d01c3d95f5dbd3a4bb181cb70dacd44135a8b/synapse/handlers/sync.py#L603-L604

Unfamiliar with this. It looks like potential_recents is of size 1 and and loaded_recents both contain the duplicate event.

DMRobertson commented 2 years ago

Oh god, I completely missed Andrew's comment https://github.com/matrix-org/synapse/issues/9768#issuecomment-816680734

DMRobertson commented 2 years ago

I don't really understand the purpose of potential_recents, to be honest. Let's assume that both, recents and loaded_recents are correct. Is there a way to deduplicate when we extend loaded_recents with recents?

I'm not sure how to merge recents into loaded_events in the former case---I don't think an EventBase knows about a topological ordering.

DMRobertson commented 2 years ago

The spec notes the following:

Further, like other members, the user’s own membership event is eligible for being considered redundant by the server. When a sync is limited, the server MUST return membership events for events in the gap (between since and the start of the returned timeline), regardless as to whether or not they are redundant. This ensures that joins/leaves and profile changes which occur during the gap are not lost.

Note that the default behaviour of state is to include all membership events, alongside other state, when lazy-loading is not enabled.

So I think that might explain what potential_recents is trying to do.

As for ordering, there's a warning infobox here which says

Events are ordered in this API according to the arrival time of the event on the homeserver.

which is presumably the stream ordering.

DMRobertson commented 2 years ago

I think #1597 is the oldest report of this. #1995 is related.