Messages in threads appear in reverse order (Element)
Steps to reproduce
- Create a thread, send some messages
- Restart client to sync again
- Open thread
- See messages in reverse order
https://github.com/element-hq/element-web/assets/29222413/d26931a3-3640-4c62-b107-e652191b64bc
(see element-hq/element-web#27664)
Activity
-
Newest first Oldest first
-
Show all activity Show comments only Show history only
- Import User added bug label · Imported
added bug label
- Author Contributor
I'm flailing around with this problem @ https://github.com/isosphere/conduwuit/tree/504_sort_threads
my operating understanding:
-
PduEvent.origin_server_ts
should hypothetically be useful for sorting chronologically - that field is set by the server on receipt 1
It doesn't seem to matter if I sort by
origin_server_ts
forwards or backwards: either way the way it looks in the clients is unchanged. element-desktop shows this after a reload but element-android and element-web is consistently2 in reverse order.I think this is an Element issue; I can't reproduce it in nheko. I'm pretty sure my fork is ordering the thread response before sending it, chronologically, from earliest timestamp to latest. Element Android and Element Web both show these in reverse order with descending timestamps. Chronology is consistently fine in nheko.
IMO data ordering isn't the server's job. It's a display issue.
-
- Author Contributor
The threads endpoint I was messing with above is the wrong one. That endpoint is for when you go to a room and click "threads" in a client to fetch a list of all threads. There may well be an issue on our end here, I'm trying to troubleshoot it w/ the chromium network panel.
I think the right endpoint is "/sync".
Here's a capture which is the result of putting my laptop in airplane mode, sending the following messages using my phone, disabling airplane mode, and capturing the result. The sequence of messages is "nlshf" -> reply in thread -> 1 -> 2 -> 3 -> 4:
[...] "timeline": { "prev_batch": "58646", "events": [ { "content": { "body": "nlshf", "msgtype": "m.text" }, "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk", "origin_server_ts": 1720626345304, "sender": "@matt:m.dataheck.com", "type": "m.room.message", "unsigned": { "age": 1, "m.relations": { "m.thread": { "count": 4, "current_user_participated": true, "latest_event": { "content": { "body": "4", "m.relates_to": { "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk", "is_falling_back": true, "m.in_reply_to": { "event_id": "$DIqPUcZ7yTeMdlx-Nf7MXdv9PRLhg_LKpq2TRObRquI" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$z5fzbFGE3BydKKqqtLrEfioUwAeTOU0r64adQtPRzFI", "origin_server_ts": 1720626354182, "room_id": "!7Ua1tGkTuvAmcrnJiO:m.dataheck.com", "sender": "@matt:m.dataheck.com", "type": "m.room.message", "unsigned": { "transaction_id": "$local.01d151db-a767-4352-a40f-b10f038308c6" } } } }, "transaction_id": "$local.3402b02b-95de-4a9f-a74a-46c8c489ced2" } }, { "content": { "body": "1", "m.relates_to": { "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk", "is_falling_back": true, "m.in_reply_to": { "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$MqDXzGxN_nt_-AxNKD2doF9WuXvA_Cmk86NkOb1_iTk", "origin_server_ts": 1720626351359, "sender": "@matt:m.dataheck.com", "type": "m.room.message", "unsigned": { "age": 1, "transaction_id": "$local.ad221e34-bc98-41fc-b16b-80664e3d8a62" } }, { "content": { "body": "2", "m.relates_to": { "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk", "is_falling_back": true, "m.in_reply_to": { "event_id": "$MqDXzGxN_nt_-AxNKD2doF9WuXvA_Cmk86NkOb1_iTk" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$6ZpxlqtqtKRw5wMORxUqEeq2lmQqx1mNBWxGnXFa1VY", "origin_server_ts": 1720626352032, "sender": "@matt:m.dataheck.com", "type": "m.room.message", "unsigned": { "age": 1, "transaction_id": "$local.f85f9416-3d26-4115-babf-fda11553c2f8" } }, { "content": { "body": "3", "m.relates_to": { "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk", "is_falling_back": true, "m.in_reply_to": { "event_id": "$6ZpxlqtqtKRw5wMORxUqEeq2lmQqx1mNBWxGnXFa1VY" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$DIqPUcZ7yTeMdlx-Nf7MXdv9PRLhg_LKpq2TRObRquI", "origin_server_ts": 1720626353399, "sender": "@matt:m.dataheck.com", "type": "m.room.message", "unsigned": { "age": 1, "transaction_id": "$local.9aba6387-0dd4-4e86-9e62-2026f63cd547" } }, { "content": { "body": "4", "m.relates_to": { "event_id": "$Vyl3TjcdfsI-8AD5JudPkuqVhJuxJqHSOsuq2ZUM7fk", "is_falling_back": true, "m.in_reply_to": { "event_id": "$DIqPUcZ7yTeMdlx-Nf7MXdv9PRLhg_LKpq2TRObRquI" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$z5fzbFGE3BydKKqqtLrEfioUwAeTOU0r64adQtPRzFI", "origin_server_ts": 1720626354182, "sender": "@matt:m.dataheck.com", "type": "m.room.message", "unsigned": { "age": 1, "transaction_id": "$local.01d151db-a767-4352-a40f-b10f038308c6" } } ] }, [...]
It looks like this in Element Desktop:
If I mouse over the timestamps, they look right i.e.: "1" has a timestamp a few seconds yonger than "4".
This response looks good to me. Any client should be able to use that and reproduce the content in the correct order
- Author Contributor
Here's a capture between element and synapse.
"timeline": { "events": [ { "type": "m.room.message", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "1", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY" }, "is_falling_back": true } }, "origin_server_ts": 1721171805468, "unsigned": { "age": 23055 }, "event_id": "$2OA5pqKmifrtyEmjbc_6tbJDm6rmsCCTXJ12egorYDA" }, { "type": "m.room.message", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "2", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$2OA5pqKmifrtyEmjbc_6tbJDm6rmsCCTXJ12egorYDA" }, "is_falling_back": true } }, "origin_server_ts": 1721171806444, "unsigned": { "age": 22079 }, "event_id": "$T1DcOiCSWiLZbhNynC42gIFnANNg3Rz4hgNuuLXcU7M" }, { "type": "m.room.message", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "3", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$T1DcOiCSWiLZbhNynC42gIFnANNg3Rz4hgNuuLXcU7M" }, "is_falling_back": true } }, "origin_server_ts": 1721171807659, "unsigned": { "age": 20864 }, "event_id": "$U59vv0DEWtbSi8aTejoZ8JJwb6CFY-1Xi2IjBdSIQ0Q" }, { "type": "m.room.message", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "4", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$U59vv0DEWtbSi8aTejoZ8JJwb6CFY-1Xi2IjBdSIQ0Q" }, "is_falling_back": true } }, "origin_server_ts": 1721171808453, "unsigned": { "age": 20070 }, "event_id": "$R4AYXbSH9VnH5b0j8uBziJ8zO3R2riPMbPKBvdmWIlE" } ], "prev_batch": "s28_934_2_15_14_1_1_10_0_1", "limited": false }
Comparisons
The chronological relationships look good as far as I can see here; there's a sort of linked list that makes sense in the same way for both server responses.
I notice that conduwuit's unsigned age is always 1, which is not the case of the synapse side. Could element be using this parameter for sorting?
That's the only thing that stands out to me.
- Author Contributor
This is a synposis including details talked about in the conduwuit matrix group.
The only difference that looks significant to me between Synapse and Conduwuit is that Synapse's unsigned age parameter varies in descending order from oldest to newest messsage, and Conduwuit's value is always 1.
EDIT: We're now dynamically calculating age as of #531, but the issue persists. There must be a difference I have not caught.
Here's where age was hardcoded to 1: https://github.com/timokoesters/conduit/commit/acfe381dd3064512272f8f47ea4dd388c04f1c39
Here's what the spec says about it: https://spec.matrix.org/v1.11/client-server-api/#room-event-format
The time in milliseconds that has elapsed since the event was sent. This field is generated by the local homeserver, and may be incorrect if the local time on at least one of the two servers is out of sync, which can cause the age to either be negative or greater than it actually is.
- Author Contributor
/sync might not be the right endpoint. Looking at the requests from Element it seems that there is an issue with /relations where it keeps requesting the same events multiple times. This might be related to the fact that /relations returns events in chronological order even though
dir=b
is given for reverse order. (just guessing though) - Author Contributor
The issue most likely lies in underlying event relations code, specifically this line that seems to ignore the direction: https://github.com/girlbossceo/conduwuit/blob/main/src%2Fservice%2Frooms%2Fpdu_metadata%2Fmod.rs#L100
Not sure why or what that TODO is for, if I have some time I can figure out what it really means and see if it's as simple as just changing this.
- Author Contributor
The issue most likely lies in underlying event relations code, specifically this line that seems to ignore the direction: https://github.com/girlbossceo/conduwuit/blob/main/src%2Fservice%2Frooms%2Fpdu_metadata%2Fmod.rs#L100
I set a breakpoint at that line and it does not get tripped by a new user joining a test room and clicking an existing thread, nor when starting a new thread and adding to it. I checked my environment by setting a breakpoint on the "typing" service and that tripped.
The function does get called though;
dir
isDirection::Backward
which is the default value according toruma_client_api
.Relevant Matrix spec section for relations: https://spec.matrix.org/v1.11/client-server-api/#relationships-api
This is what it says about the
dir
parameter:Optional (default b) direction to return events from. If this is set to f, events will be returned in chronological order starting at from. If it is set to b, events will be returned in reverse chronological order, again starting at from.
Looks like reverse order is the spec-default behaviour, and what
element-desktop
requests in its GET variables by default:dir=b
.I forced
dir
toDirection::Forward
just before ourmatch dir
inpaginate_relations_with_filter
and it seems to make things appear in the right order: i.e.: chronological.I think element is just wrong
- Author Contributor
Can you compare the direction behaviour request responses between Synapse and conduwuit?
- Author Contributor
Can you compare the direction behaviour request responses between Synapse and conduwuit?
Clients: 2x
element-desktop
executed viaflatpak
with different profiles. Both clients connected to the same server.Synapse
GET
https://s.dataheck.com/_matrix/client/v1/rooms/!fpdVzFVTBbeJtYJCUS%3As.dataheck.com/relations/%24MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY?dir=b
response
{ "chunk": [ { "type": "m.room.message", "room_id": "!fpdVzFVTBbeJtYJCUS:s.dataheck.com", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "4", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$U59vv0DEWtbSi8aTejoZ8JJwb6CFY-1Xi2IjBdSIQ0Q" }, "is_falling_back": true } }, "origin_server_ts": 1721171808453, "unsigned": { "age": 2304609955 }, "event_id": "$R4AYXbSH9VnH5b0j8uBziJ8zO3R2riPMbPKBvdmWIlE", "user_id": "@matt:s.dataheck.com", "age": 2304609955 }, { "type": "m.room.message", "room_id": "!fpdVzFVTBbeJtYJCUS:s.dataheck.com", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "3", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$T1DcOiCSWiLZbhNynC42gIFnANNg3Rz4hgNuuLXcU7M" }, "is_falling_back": true } }, "origin_server_ts": 1721171807659, "unsigned": { "age": 2304610749 }, "event_id": "$U59vv0DEWtbSi8aTejoZ8JJwb6CFY-1Xi2IjBdSIQ0Q", "user_id": "@matt:s.dataheck.com", "age": 2304610749 }, { "type": "m.room.message", "room_id": "!fpdVzFVTBbeJtYJCUS:s.dataheck.com", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "2", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$2OA5pqKmifrtyEmjbc_6tbJDm6rmsCCTXJ12egorYDA" }, "is_falling_back": true } }, "origin_server_ts": 1721171806444, "unsigned": { "age": 2304611964 }, "event_id": "$T1DcOiCSWiLZbhNynC42gIFnANNg3Rz4hgNuuLXcU7M", "user_id": "@matt:s.dataheck.com", "age": 2304611964 }, { "type": "m.room.message", "room_id": "!fpdVzFVTBbeJtYJCUS:s.dataheck.com", "sender": "@matt:s.dataheck.com", "content": { "msgtype": "m.text", "body": "1", "m.relates_to": { "rel_type": "m.thread", "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY", "m.in_reply_to": { "event_id": "$MmkcrQpY6rGhBZY4JSNk-Oej0t9itZd01VBYmHSZlJY" }, "is_falling_back": true } }, "origin_server_ts": 1721171805468, "unsigned": { "age": 2304612940 }, "event_id": "$2OA5pqKmifrtyEmjbc_6tbJDm6rmsCCTXJ12egorYDA", "user_id": "@matt:s.dataheck.com", "age": 2304612940 } ] }
It requested reverse chronological order, and that's what it got. Shows fine in
element-desktop
: chronological. I visually inspected 3 other similar requests for different threads, they match this behaviour.Conduwuit
(I removed my
dir
overriding test for this)GET
http://sharedbudgets.local/_matrix/client/v1/rooms/!fhpvWsfeOxpE5JKZCB%3Asharedbudgets.local/relations/%24xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU?dir=b
1response
{ "chunk": [ { "content": { "body": "1", "m.mentions": {}, "m.relates_to": { "event_id": "$xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU", "is_falling_back": true, "m.in_reply_to": { "event_id": "$xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$jA2D_6tXtlhFQi7EYBUZctS-I6CdJBInBtvZ4EuMZNE", "origin_server_ts": 1723477259838, "room_id": "!fhpvWsfeOxpE5JKZCB:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": {} }, { "content": { "body": "2", "m.mentions": {}, "m.relates_to": { "event_id": "$xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU", "is_falling_back": true, "m.in_reply_to": { "event_id": "$jA2D_6tXtlhFQi7EYBUZctS-I6CdJBInBtvZ4EuMZNE" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$60IAks924vMegDh8RCsBL4sJc2o0F6U_n3XBBWlNlYA", "origin_server_ts": 1723477260171, "room_id": "!fhpvWsfeOxpE5JKZCB:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": {} }, { "content": { "body": "3", "m.mentions": {}, "m.relates_to": { "event_id": "$xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU", "is_falling_back": true, "m.in_reply_to": { "event_id": "$60IAks924vMegDh8RCsBL4sJc2o0F6U_n3XBBWlNlYA" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$CS1UCmIZ_Lvo-sZIQRdLngS0c7zC94I3ZiknAU2WafM", "origin_server_ts": 1723477260496, "room_id": "!fhpvWsfeOxpE5JKZCB:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": {} }, { "content": { "body": "4", "m.mentions": {}, "m.relates_to": { "event_id": "$xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU", "is_falling_back": true, "m.in_reply_to": { "event_id": "$CS1UCmIZ_Lvo-sZIQRdLngS0c7zC94I3ZiknAU2WafM" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$LP83ESqrzGuXVNExrt3fpVDJgqrBHVXXoogKt75GGlQ", "origin_server_ts": 1723477260820, "room_id": "!fhpvWsfeOxpE5JKZCB:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": {} }, { "content": { "body": "5", "m.mentions": {}, "m.relates_to": { "event_id": "$xdd718Rv2y456IfBRnGN_hjlqgkrcI0QpWJ0dL7zLdU", "is_falling_back": true, "m.in_reply_to": { "event_id": "$LP83ESqrzGuXVNExrt3fpVDJgqrBHVXXoogKt75GGlQ" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$DPWJ4TDT5XTrGvfKSHfpVZB9Er281O5bvGsKfIB06x8", "origin_server_ts": 1723477261258, "room_id": "!fhpvWsfeOxpE5JKZCB:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": {} } ], "next_batch": "1337", "prev_batch": "18446744073709551615" }
Okay, maybe
conduwuit
is wrong.paginate_relations_with_filter
sees that the client requesteddir
=Direction::Backward
but we're actually returning data chronologically.I think we can cut this function down in half too, there's some repetition going on in there.
-
sharedbudgets.local = 127.0.0.1 ↩
-
- Author Contributor
Here's a response snippet from the commit referenced above; it's now in reverse order as requested by element:
Response
{ "chunk": [ { "content": { "body": "3", "m.mentions": {}, "m.relates_to": { "event_id": "$7jry-CavwdYk3DEWIgzPEJ8ml9c9HvA7hhqkuV2oxKg", "is_falling_back": true, "m.in_reply_to": { "event_id": "$42gs7TDdW5voOQFpNgRfiJWzB6gYK83dk-mMRruzXSM" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$TIX0EEGSi-Fsfyrwfx1F8JipvwAzZ8jOjHZ83zggXq8", "origin_server_ts": 1723814631141, "room_id": "!AX4HOUVizHqi0FSSTZ:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": { "transaction_id": "m1723814631088.3" } }, { "content": { "body": "2", "m.mentions": {}, "m.relates_to": { "event_id": "$7jry-CavwdYk3DEWIgzPEJ8ml9c9HvA7hhqkuV2oxKg", "is_falling_back": true, "m.in_reply_to": { "event_id": "$_M8VQjBJm3ivFBQnHwfmXWOtE1JA7fXnlIl0CC5VZdE" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$42gs7TDdW5voOQFpNgRfiJWzB6gYK83dk-mMRruzXSM", "origin_server_ts": 1723814630847, "room_id": "!AX4HOUVizHqi0FSSTZ:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": { "transaction_id": "m1723814630790.2" } }, { "content": { "body": "1", "m.mentions": {}, "m.relates_to": { "event_id": "$7jry-CavwdYk3DEWIgzPEJ8ml9c9HvA7hhqkuV2oxKg", "is_falling_back": true, "m.in_reply_to": { "event_id": "$7jry-CavwdYk3DEWIgzPEJ8ml9c9HvA7hhqkuV2oxKg" }, "rel_type": "m.thread" }, "msgtype": "m.text" }, "event_id": "$_M8VQjBJm3ivFBQnHwfmXWOtE1JA7fXnlIl0CC5VZdE", "origin_server_ts": 1723814630419, "room_id": "!AX4HOUVizHqi0FSSTZ:sharedbudgets.local", "sender": "@matt:sharedbudgets.local", "type": "m.room.message", "unsigned": { "transaction_id": "m1723814630381.1" } } ], "next_batch": "1675", "prev_batch": "1682" }
Looks good in the client as well.
PR opened: #555
- Author Contributor
This should be fixed now with !555 (merged)
- Import User closed · Imported
closed
- Author Contributor
Confirmed the latest
main
branch works for me! Thank you both!