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

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

Open
bwindels opened this issue Apr 8, 2021 · 10 comments
Open

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

bwindels opened this issue Apr 8, 2021 · 10 comments
Labels
A-Invite Inviting users to rooms and accepting invites A-Sync defects related to /sync S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.

Comments

@bwindels
Copy link
Contributor

bwindels commented Apr 8, 2021

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
Copy link
Member

richvdh commented Apr 8, 2021

suspect this has the same cause as #1995

@anoadragon453
Copy link
Member

anoadragon453 commented Apr 9, 2021

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.

loaded_recents = await filter_events_for_client(
self.storage,
sync_config.user.to_string(),
loaded_recents,
always_include_ids=current_state_ids,
)
loaded_recents.extend(recents)

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:

if potential_recents:
recents = sync_config.filter_collection.filter_room_timeline(
potential_recents
)

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.

@anoadragon453 anoadragon453 added S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. labels Apr 9, 2021
@DMRobertson
Copy link
Contributor

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
Copy link
Contributor

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:

if since_token:
room_changes = await self._get_rooms_changed(
sync_result_builder, ignored_users
)
tags_by_room = await self.store.get_updated_tags(
user_id, since_token.account_data_key
)
else:
room_changes = await self._get_all_rooms(sync_result_builder, ignored_users)
tags_by_room = await self.store.get_tags_for_user(user_id)

DMRobertson added a commit to matrix-org/complement that referenced this issue Nov 29, 2021
@DMRobertson DMRobertson self-assigned this Nov 29, 2021
@DMRobertson
Copy link
Contributor

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

@DMRobertson
Copy link
Contributor

I've narrowed it down to here:

loaded_recents.extend(recents)
recents = loaded_recents

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

@DMRobertson
Copy link
Contributor

Oh god, I completely missed Andrew's comment #9768 (comment)

@DMRobertson
Copy link
Contributor

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?

  • loaded_recents is a subset of events which is returned by either get_room_events_stream_for_room or get_recent_events_for_room.
  • Both claim to return results in ascending order.
    • get_recent_events_for_room claims to use topological ordering, and seems to tie-break on stream ordering.
    • get_room_events_stream_for_room uses stream ordering.

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
Copy link
Contributor

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 DMRobertson removed their assignment Feb 8, 2022
@MadLittleMods MadLittleMods added A-Invite Inviting users to rooms and accepting invites A-Sync defects related to /sync labels May 16, 2022
@DMRobertson
Copy link
Contributor

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

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A-Invite Inviting users to rooms and accepting invites A-Sync defects related to /sync S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Development

No branches or pull requests

5 participants