Event got sent but not synced back down everywhere

The event in question is https://app.element.io/#/room/!RbKRuLTvHIhArQcvjr:matrix.org/$1613561441289661rpDpF:matrix.org?via=matrix.org&via=vector.modular.im&via=t2l.io

The client that sent the event (element desktop) and my dekstop hydrogen running alongside did not get the event from sync.

On element desktop the event was black (e.g. sent) but stuck to the bottom of the room, and on hydrogen I check the storage and it showed that there was no limited sync for that room around those messages, and there is no trace of that event anywhere.

When opening my phone hydrogen an hour or so later, the event was synced down to it in the correct order.

At least T3chguy and Ryan did receive the event in the correct order.

we have also several report of that on android
https://github.com/matrix-org/element-android-rageshakes/issues/20724
https://github.com/matrix-org/element-android-rageshakes/issues/20672
https://github.com/matrix-org/element-android-rageshakes/issues/20578

I also experienced it on other client (web)

Also this issue element-hq/element-android#516

#9624

@callahad

@callahad @anoadragon453 I renamed this ticket as #9624 (which was marked as a dupe) is about the recipient and not the sender not receiving the message. FYI if this changes the severity of the bug.

Just an update: This is on our radar, but we expect it to be a pretty big yak to shave, so it's currently deferred until we can wrap up some other hairy problems 🐃

Matthew reported another instance of this today. Link and details for internal users at https://github.com/matrix-org/element-web-rageshakes/issues/5808

And another set by Matthew on Aug 10:

Room ID: !JjwYSGirOwIXEpJgzg:matrix.org
Event ID: $ZrcrvSAESv5PBzszSXpT5EahA2eQR-raFbFfSY314LQ

We should add some more logs to try and track down where the event is going missing. I'd probably do something like:

Log to the span how many rooms have changed (i.e. what's returned by _get_rooms_changed)
Add a span for each _generate_room_entry call, tagging it with room ID
Log to the span the number of events returned from the DB, and whether we hit a cache, and what tokens are used in the query
Log to the span how many events there are after filtering.
Log to the span the number of room entries and events in the response JSON just before returning

etc. The idea being that hopefully we'll be able to see if the missing event is pulled out of the DB and if so where we drop it (if we ever do).

Add logging to help debug #9424 (#10704)

And another just now...

Room ID: !KzalCNJxkqtytlbQvX:matrix.org
Event ID: $16310279891219482qXcHE:matrix.org

...and again...

Room ID: !KzalCNJxkqtytlbQvX:matrix.org
Event ID: $16311860683330067SxAox:matrix.org

Run message history backfill after creating all the rooms

@Fizzadar

@Fizzadar Hi; thanks for taking some time to write this up.

I'm still unfamiliar with MSC2716, but I think it may be useful to know the structure of the DAG to figure out what's going on here.
Is there any chance you'd be able to run the following?:

SELECT stream_ordering, type, state_key, event_id, (ej.json::json)->'prev_events' AS prev_events FROM events
LEFT JOIN event_json AS ej USING (event_id)
WHERE events.room_id ='!SjekxtmsBigrUMcMkX:beeper-dev.com' ORDER BY stream_ordering ASC;

If the room has been used more since your last message, feel free to trim it to the range that was there previously.

@reivilibre

@reivilibre thanks for looking into this; query results:

LEFT JOIN event_json AS ej USING (event_id)
WHERE events.room_id ='!SjekxtmsBigrUMcMkX:beeper-dev.com' ORDER BY stream_ordering ASC;
 stream_ordering |             type             |                          state_key                           |                   event_id                   |                   prev_events
-----------------+------------------------------+--------------------------------------------------------------+----------------------------------------------+--------------------------------------------------
         -113203 | org.matrix.msc2716.insertion |                                                    | $G5GLwX6lc8MXKqwauoM1p9lkLD6S5GfwcosFlPra0ws | []
         -113202 | m.room.encrypted             |                                                    | $I3PsF44AMu5I_XOZQ2Hm1cOhcdLJCbA8NcAMS69hLEE | ["$G5GLwX6lc8MXKqwauoM1p9lkLD6S5GfwcosFlPra0ws"]
         -113201 | m.room.encrypted             |                                                    | $hIO0ZI-ZYr8gWGkWtvBiPfCA0jKdjiZP7PCnEfuutTY | ["$I3PsF44AMu5I_XOZQ2Hm1cOhcdLJCbA8NcAMS69hLEE"]
         -113200 | m.room.encrypted             |                                                    | $-jWSmA7NJ1dbl5b86K8FAKN2ydt-qoOw8ftCdSEN4A4 | ["$hIO0ZI-ZYr8gWGkWtvBiPfCA0jKdjiZP7PCnEfuutTY"]
         -113199 | m.room.encrypted             |                                                    | $5EtpKKW7g5HV5oCweU6vlbGjptR095p-kZSSSy2tBgs | ["$-jWSmA7NJ1dbl5b86K8FAKN2ydt-qoOw8ftCdSEN4A4"]
         -113198 | m.room.encrypted             |                                                    | $5aVzqGvybXzV3Xj3AwA8SQKqp2X2Z7RLH7IGX5VBeX4 | ["$5EtpKKW7g5HV5oCweU6vlbGjptR095p-kZSSSy2tBgs"]
         -113197 | org.matrix.msc2716.batch     |                                                    | $KkSRlRidPiOkkLEuiHs3gWLyCqCdQTHAVYJxzhDIzcM | ["$5aVzqGvybXzV3Xj3AwA8SQKqp2X2Z7RLH7IGX5VBeX4"]
         -111135 | org.matrix.msc2716.insertion |                                                    | $LQBf_c9-1stBXkPOLqZwkJgMg5YBCp448qcUwKLN6ks | []
         -111134 | m.room.encrypted             |                                                    | $RzKCB8rV0a9jfQVfbJeGvgGIZtT_X7ODb-78LUhXpXs | ["$LQBf_c9-1stBXkPOLqZwkJgMg5YBCp448qcUwKLN6ks"]
         -111133 | org.matrix.msc2716.batch     |                                                    | $l_jGmPdlA73wDzS3_gRwC67co1pTnx9-QBufta10xWI | ["$RzKCB8rV0a9jfQVfbJeGvgGIZtT_X7ODb-78LUhXpXs"]
         -111132 | org.matrix.msc2716.insertion |                                                    | $_mT6Awgb70IjwseWpCUeU0O4tm_iT7OBe4IPLJYUHUU | ["$a6xyChJTR8wJLsfYfGI8Tu1W5cXrtohkBRdwCSsyG68"]
         2633404 | m.room.create                |                                                    | $ZMCw8gIYOeNmC2mGNKiAdxbRdwuhDiA9gNaM8EwDlRM | []
         2633421 | m.room.member                | @_adam4_whatsapp_xxx:beeper-dev.com                | $a6LZbYMvr5yYRcFc0uethSHLVC_0l7LRUr0nCZXB2lQ | ["$ZMCw8gIYOeNmC2mGNKiAdxbRdwuhDiA9gNaM8EwDlRM"]
         2633434 | m.room.power_levels          |                                                    | $S2rnt0m3dfbgC0ySGI3RGSdIjNqhgjjilZ2Gm7jGtvg | ["$a6LZbYMvr5yYRcFc0uethSHLVC_0l7LRUr0nCZXB2lQ"]
         2633448 | m.room.join_rules            |                                                    | $5hkAty1mFIMtuFINEh8wA3OyIgnO6Qxh1HgCTT9c1p0 | ["$S2rnt0m3dfbgC0ySGI3RGSdIjNqhgjjilZ2Gm7jGtvg"]
         2633461 | m.room.history_visibility    |                                                    | $nNR6iQSvWPpoKRvfpXJXU_sWpnk8eCwTFJD9zwC2rfo | ["$5hkAty1mFIMtuFINEh8wA3OyIgnO6Qxh1HgCTT9c1p0"]
         2633469 | m.room.guest_access          |                                                    | $iNJMDkjnFwBekoCZASqZmiNtH8UMLsPc_1VHJD6IFpU | ["$nNR6iQSvWPpoKRvfpXJXU_sWpnk8eCwTFJD9zwC2rfo"]
         2633478 | m.bridge                     | net.maunium.whatsapp://whatsapp/xxx@s.whatsapp.net | $p5fs4ik0Lnj-mIbw-cjPHX_aWzx0x6O_rIrhSi8_1C8 | ["$iNJMDkjnFwBekoCZASqZmiNtH8UMLsPc_1VHJD6IFpU"]
         2633492 | uk.half-shot.bridge          | net.maunium.whatsapp://whatsapp/xxx@s.whatsapp.net | $tAZ3y00piOU_54qs0MuK-HRPivXNRBmN8x6yY5KWXkk | ["$p5fs4ik0Lnj-mIbw-cjPHX_aWzx0x6O_rIrhSi8_1C8"]
         2633503 | m.room.avatar                |                                                    | $BZOaOEhozp28cCJtdh8A6R2hKgXiuDmd1NWI2vEuyPs | ["$tAZ3y00piOU_54qs0MuK-HRPivXNRBmN8x6yY5KWXkk"]
         2633515 | m.room.encryption            |                                                    | $qTv8IJZIdlH_3S7atbGTrd-7p7UEt4siocS0vz8-K3Y | ["$BZOaOEhozp28cCJtdh8A6R2hKgXiuDmd1NWI2vEuyPs"]
         2633523 | m.room.name                  |                                                    | $joClbFehqiqiVOuYYDWGJeYaozJnaccZgVog8j4bB6g | ["$qTv8IJZIdlH_3S7atbGTrd-7p7UEt4siocS0vz8-K3Y"]
         2633533 | m.room.topic                 |                                                    | $WP0ALeVvT2oCRSt9qs4_bE2O5AKsu_4GqbTCPFwaKa4 | ["$joClbFehqiqiVOuYYDWGJeYaozJnaccZgVog8j4bB6g"]
         2633547 | m.room.member                | @_adam4_whatsapp_bot:beeper-dev.com                | $hq4kZZPt4ItYdBF_I_AVITFHOZOZ2b_Av8ss3F06byg | ["$WP0ALeVvT2oCRSt9qs4_bE2O5AKsu_4GqbTCPFwaKa4"]
         2633571 | m.room.member                | @adam4:beeper-dev.com                              | $DyFoSr8CbRUyexbx6_yuZxgS4S7lAEHDYgldiRGnppc | ["$hq4kZZPt4ItYdBF_I_AVITFHOZOZ2b_Av8ss3F06byg"]
         2633582 | m.room.member                | @adam4:beeper-dev.com                              | $51gzIcw5d1fvbNLqYXdBwma669-H8DZlz0UzsavMBbU | ["$DyFoSr8CbRUyexbx6_yuZxgS4S7lAEHDYgldiRGnppc"]
         2633590 | m.room.member                | @_adam4_whatsapp_bot:beeper-dev.com                | $Sx9mswlxUJs1rRL4UyHARmY7V0h8_cH_c_ZDnwTn3cc | ["$51gzIcw5d1fvbNLqYXdBwma669-H8DZlz0UzsavMBbU"]
         2633601 | fi.mau.dummy.portal_created  |                                                    | $a6xyChJTR8wJLsfYfGI8Tu1W5cXrtohkBRdwCSsyG68 | ["$Sx9mswlxUJs1rRL4UyHARmY7V0h8_cH_c_ZDnwTn3cc"]
         2633614 | fi.mau.dummy.pre_backfill    |                                                    | $E97WApcmVmCJ6nt2WL3TnuxhyCLnPl1dt-t6p25ZLwY | ["$a6xyChJTR8wJLsfYfGI8Tu1W5cXrtohkBRdwCSsyG68"]
         2633633 | fi.mau.dummy.backfill_end    |                                                    | $NILDi9SfVDgaW72alIEsc5ESzdJSoLip_c7klMAeuPo | ["$E97WApcmVmCJ6nt2WL3TnuxhyCLnPl1dt-t6p25ZLwY"]
(30 rows)```

@Fizzadar

@Fizzadar Oooh, interesting (maybe, likely need to think about it! whilst reading the batch send MSC!).
What I find interesting is that there are multiple events with no prev_events (which is what I expect from the batch sending stuff) but no later events have more than 1, to merge the forks together. (Only making remarks so I can keep track of this; not sure if that's important or not.)
Are those all the events in the room; if not, are there any that merge later on?

@reivilibre

@reivilibre that's everything in the room! We left it alone after replicating the issue in case this data is useful :)

I wonder if it makes sense to split out our line of discussion, because presumably this is something to do with batch_send and not whatever the original issue was back in Feb 2021.

Run message history backfill after creating all the rooms

@bradtgmurray

Given the complexity of how Synapse's implementation ofMSC2716 interacts with the room DAG, it does appear likely that the bug in your case @bradtgmurray is related to batch_send code - specifically the /sync bit of it. Moving and tackling this case in a separate issue would be ideal.

I see that mautrix/whatsapp#463 has been linked to this issue though - do you find that backfilling the room works to recover the missing event in all cases?

The whatsapp PR is just us trying things attempting to work around the issue, haven't gotten to the bottom of it yet.

Do you know if the DAG we posted above looks correct to you?

I've split out relevant parts into a new issue #12281, let's continue discussions there.

@MatMaul

I'm not really sure what's going on here. It seems like there are:

some really old reports, which predate Erik's fix in Fix race in MultiWriterIdGenerator #11045
a bunch of reports from Matthew, which he later seems to have decided was an E2E bug
a fleeting report from @MatMaul, which we were unable to reproduce or investigate.
a bunch of discussion with @bradtgmurray / @Fizzadar, which seems to have been factored out to a a separate issue, and fixed.

In any case, there is probably more than one bug here, and lumping further reports into a single issue is likely to cause confusion.

As such, can this be closed? I don't think there's any useful context here.

@richvdh

@richvdh I agree - this issue has become a bit of a mishmash of related problems, with an awful lot of old comments to read before hitting content relevant to today's ecosystem.

Closing this issue as it looks to have run its course. Please file a new issue if you have one; potentially linking this one if relevant.

Pullup ticket #6538 - requested by gdt

Navigation Menu

Repository navigation

Event got sent but not synced back down everywhere #9424

32 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Event got sent but not synced back down everywhere #9424

Description

Activity

BillCarsonFr commented on Mar 16, 2021

BillCarsonFr commented on Mar 16, 2021

bwindels commented on Mar 18, 2021

callahad commented on Mar 24, 2021

richvdh commented on Jul 12, 2021

anoadragon453 commented on Aug 12, 2021

erikjohnston commented on Aug 12, 2021

ara4n commented on Sep 7, 2021

ara4n commented on Sep 9, 2021

32 remaining items

reivilibre commented on Mar 17, 2022

Fizzadar commented on Mar 17, 2022

reivilibre commented on Mar 17, 2022

Fizzadar commented on Mar 17, 2022

bradtgmurray commented on Mar 22, 2022

anoadragon453 commented on Mar 23, 2022

bradtgmurray commented on Mar 23, 2022

Fizzadar commented on Mar 24, 2022

richvdh commented on May 19, 2022

anoadragon453 commented on May 19, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions