Open dgobaud opened 6 years ago
I can confirm having seen what sounds the same. I'm unsure if I was on Linux or MacOS at the time, but I had conversations load up completely scrambled. As in this report, there was significant time between messages and they appeared effectively random in order. I had to look at my phone as the point of authority to have an idea what the other party was actually saying.
I remember restarting the client but it did not work.
On the same day I also had a case where one message received was simply "missing" on the desktop client despite restarting it.
This is happening to me when opening (or switching to) Signal on MacOS after conversing on Android.
Also experiencing the same issue using the Android client and the Signal Desktop for Windows client.
+1, Signal on OS X and Android
Same on Linux so not platform specific it seems.
And restarting the program doesn't fix the order. (it could have if we were lucky ^^")
One thing to watch for is specifically when this happens. There seems to be a correlation between this out-of-order behavior and reconnections. So if you have Signal running and close your laptop then come back, you can end up with messages out of order. But if you had it closed and start up after opening your laptop, it would be in order. I'd love to know if that matches what you're seeing.
@scottnonnenberg-signal the reordering issue identified almost a year ago does not correlate with reconnections only, but also with normal connections (aka app starts).
Is there another issue that happens only with reconnects?
@Trolldemorted I encourage you to try it, see if it repros for you. :0)
I don't have any Signal-Desktop slaves at the moment, but all of my slaves are hit by severe reorderings as well (I assumed it was due to #1826). You spoke specifically of reconnects - do you assume there is a Signal-Desktop specific bug that is related to its reconnects?
And can you estimate when #1826 will be fixed? It is hard to know whether you are hit by #1826 or a different bug, so if you would address that one tracking down remaining ones will become much easier :)
@Trolldemorted No, I suspect that reconnect is causing another server bug, not a Desktop bug.
Regarding #1826, it's pretty easy to rule that out. If you know you got no other new messages during the test period, then that issue, 'queue-jumping,' isn't the problem. As for when it will be fixed, we're hiring in server roles: https://signal.org/workworkwork/#server
Are you sure this is related to reconnects? From the server's perspective, a reconnect and a new start do look the same, don't they?
Ruling that out during tests is easy indeed, but that doesn't help too much with bug reports from normal users. I encounter reordered messages frequently (they are polled with short-lived background tasks), but I assumed that it was still the queue jumping issue, just blurred by more caching on the server.
If you are certain that no server changes could have caused messages that were sent in the "near past" to be sent to a connecting client using the "queue-jumping" method, we are indeed facing another issue here (that imo occurs if the ws connection is closed before the queue was drained) :(
I really would have applied, but unfortunately you are considering US-based employees only. Would you merge PRs from the community, or appreciate help in tracking down the server issues? I really hope you find someone soon, the frequent reordering and dropping of messages are really bad for signal's reputation.
This has happened for me at least twice now.
https://debuglogs.org/c7e46c6128643a796b30f22682ac9f6e5aab6c525de41b07b04330dc0cf02127 Message 1533204513381 appears before messages 1533169376442 and 1533205258960 even if it should appear after them.
I made some changes in the last few beta builds that should make this better. Please let me know how things go on v1.15.0-beta.9
or higher. Thanks!
Still happening with 1.18.0
@philkunz You haven't previously commented above. What is still happening, exactly? Please describe exactly what you're seeing, ideally with message 'sent id' values for the out-of-order messages (from the Message details screen) and a full debug log.
I can confirm that this happens between Linux on desktop and ios on phone.
Same issue here, deleting the conversation on Linux client is the only solution I've found.
Ubuntu 18.04.1 LTS Signal version 1.21.0
I noticed this today. I had my laptop and Signal client open for a period without issue, but then noticed the issue started occurring. I updated the group avatar, and both desktop and android properly showed the note about the group updating, then without going offline the conversation continued and I observed messages were appearing out of order, including messages I sent from the desktop client.
Screenshots: Desktop, wrong order: Desktop message info for each sent/received message (in order they appear on the desktop client):
Android, correct order:
Desktop logs: https://debuglogs.org/7a336ce42d104656d51cac7163c48bca102bb261f7cb134d37aed1dc47364148
Android logs: https://debuglogs.org/65b5527f46023c93c0a015b9a752b002f6627723a74ede6f30d18daca272e3a2
It seems Signal is using Time Received
instead of Time Sent
to sort messages which IMHO is incorrect? I believe time received is device-specific whereas sent is message-specific?
@adioe3 You're right. We don't trust the sent time provided by sending clients. We only trust the order that we received the message in.
@scottnonnenberg-signal are the messages fetched in FIFO or FILO ordering? Maybe that's the cause of the bug?
It's FIFO queue, very clearly. Messages appear in order most of the time after all!
I don't know anything about the code base or internal design, but if the order is based on the time of receipt, is it possible this is caused by transport level problems? For example, is it possible the client somehow ends up with multiple outstanding long polls (or some equivalent) that may result in duplicate delivery from competing background tasks with different times? (For example, a retry is attempted on timeout without synchronizing with the timed out task to ensure it is stopped prior to determining what the most recently received message is.)
This happened to me with a particularly long time-lag -- messages from last week appearing after messages sent right now.
Last message I received:
Sent | Sunday, March 31, 2019 10:39 AM (1554043167016) |
---|---|
Received | Sunday, March 31, 2019 10:39 AM (1554043170890) |
Last message I sent:
Sent | Sunday, March 31, 2019 10:40 AM (1554043216271) |
---|---|
Received | Sunday, March 31, 2019 10:40 AM (1554043216271) |
The message from March 24:
Sent | Sunday, March 24, 2019 10:35 AM (1553438102872) |
---|---|
Received | Sunday, March 31, 2019 2:16 PM (1554056216572) |
@scottnonnenberg-signal What are your thoughts on adding a client option to sort by sent date as a workaround until the root cause can be fixed? Even if it's off by default or hidden away in a CLI option/config file, it would at least give users suffering from this issue a stopgap option.
I'm also experiencing this issue on Windows 10 with Signal Desktop v1.27.3 .
Messages don't get reordered correctly after restarting the app.
@fynnay More details on exactly how messages are out of order would really help. How many total? Looks like it's just one message in that screenshot? How many conversations did this happen in?
@scottnonnenberg-signal So far it only happened with this one message. When I received it on my phone I afterwards opened the Desktop app, where the new message appeared to be missing although it had only been inserted further up in the conversation.
I keep getting this all the time. The messages get sorted by time received instead of time sent. Time sent is always correct but time received seems to be shuffled around. Looks like some kind of ring buffer wraparound bug or something.
It just happened to me. I will try to give as much data points as possible to help you get to the bottom of this.
First a screenshot of the miss-ordered message:
What happened:
B
hereafter). Two instances are on my private laptop; one beta (B
) and one stable instance S
The work laptop app (W
) is still offline.S
did not change the order there.Speculation:
S
. I am not completely sure if I have sent the message from B
during or short after starting S
.Things that are weird:
S
- see below.Here the timestamps as well as the individual number of the message from the message detail screen:
B
were the message was written:Sent | Freitag, 25. Oktober 2019 13:07 (1572001657763) |
---|---|
Received | Freitag, 25. Oktober 2019 13:07 (1572001657763) |
plus the debug log from B
: https://debuglogs.org/59cf06f7fb4f545e99c70c1a210f71ab2bd312be4634d479bfd79b7a4b6549f6
S
where the message was miss-ordered:Sent | Freitag, 25. Oktober 2019 13:07 (1572001657763) |
---|---|
Received | Freitag, 25. Oktober 2019 13:09 (1572001761794) |
plus the debug log from S
: https://debuglogs.org/bcd5bc6efc05c93d51138fe90918d9bc858df27e6ed5b1e055377a5635e4c9e9
Android A
which received the message correctly ordered:
screenshot:
log from A
:
https://debuglogs.org/2be86c1d037fafebe43fd216008991ee488b9f77fdef4f84c1a7e9f7b00ce67f
questions:
W
help?@rainerzufall Your scenario fits the pattern: loading a lot of messages at once, and some very recent messages are sorted older than they should be. We believe this to be a server issue; messages can jump the queue while Desktop is downloading older messages. This causes problems because, as always, Desktop sorts in the order it receives messages from the server.
You can help us verify this by providing messages that should go right before or after the out-of-order messages, as well as the messages that actually were before or after.
B
before the out-of-order message on S
[written on A
]:Gesendet | Donnerstag, 24. Oktober 2019 20:40 (1571942451957) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000774448) |
Gesendet | Donnerstag, 24. Oktober 2019 20:44 (1571942642533) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000774979) |
Gesendet | Donnerstag, 24. Oktober 2019 20:44 (1571942651655) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000774983) |
Gesendet | Donnerstag, 24. Oktober 2019 20:44 (1571942660687) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000775067) |
Gesendet | Donnerstag, 24. Oktober 2019 20:45 (1571942736058) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000775238) |
Gesendet | Freitag, 25. Oktober 2019 09:14 (1571987675477) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000776093) |
Gesendet | Freitag, 25. Oktober 2019 11:53 (1571997203879) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000778669) |
Gesendet | Freitag, 25. Oktober 2019 11:53 (1571997228674) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000778680) |
Gesendet | Freitag, 25. Oktober 2019 11:55 (1571997322347) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000778736) |
Gesendet | Freitag, 25. Oktober 2019 12:01 (1571997667768) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 12:52 (1572000778754) |
B
which is out-of-order on S
[written on B
]:Gesendet | Freitag, 25. Oktober 2019 13:07 (1572001657763) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:07 (1572001657763) |
B
after out-of-order message on S
[not 100% sure on which device they were written]:Gesendet | Freitag, 25. Oktober 2019 13:16 (1572002193951) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:16 (1572002198355) |
Gesendet | Freitag, 25. Oktober 2019 13:18 (1572002282301) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:18 (1572002286594) |
Gesendet | Freitag, 25. Oktober 2019 13:18 (1572002292164) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:18 (1572002296571) |
Gesendet | Freitag, 25. Oktober 2019 13:19 (1572002348459) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:19 (1572002349394) |
Gesendet | Freitag, 25. Oktober 2019 13:19 (1572002364358) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:19 (1572002368254) |
Gesendet | Freitag, 25. Oktober 2019 13:19 (1572002369405) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:19 (1572002373377) |
Gesendet | Freitag, 25. Oktober 2019 13:19 (1572002393130) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:19 (1572002397116) |
Gesendet | Freitag, 25. Oktober 2019 13:20 (1572002418212) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:20 (1572002422221) |
Gesendet | Freitag, 25. Oktober 2019 13:21 (1572002484371) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:21 (1572002485373) |
Gesendet | Freitag, 25. Oktober 2019 13:21 (1572002489286) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:21 (1572002490144) |
B
with A
S
before the out-of-order message:Gesendet | Mittwoch, 23. Oktober 2019 15:36 (1571837811682) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001753790) |
Gesendet | Mittwoch, 23. Oktober 2019 15:44 (1571838273579) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001754240) |
Gesendet | Mittwoch, 23. Oktober 2019 15:44 (1571838284472) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001754469) |
Gesendet | Mittwoch, 23. Oktober 2019 15:47 (1571838461297) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001754847) |
Gesendet | Mittwoch, 23. Oktober 2019 16:07 (1571839650022) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001755350) |
Gesendet | Mittwoch, 23. Oktober 2019 16:25 (1571840700275) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001755659) |
Gesendet | Mittwoch, 23. Oktober 2019 16:25 (1571840701851) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001755841) |
Gesendet | Mittwoch, 23. Oktober 2019 17:19 (1571843971908) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001756833) |
Gesendet | Mittwoch, 23. Oktober 2019 17:25 (1571844340099) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001757362) |
Gesendet | Mittwoch, 23. Oktober 2019 18:34 (1571848446367) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001757725) |
S
:Gesendet | Freitag, 25. Oktober 2019 13:07 (1572001657763) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001761794) |
S
after the out-of-order message:Gesendet | Mittwoch, 23. Oktober 2019 20:44 (1571856296094) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001766815) |
Gesendet | Mittwoch, 23. Oktober 2019 21:47 (1571860068289) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001767488) |
Gesendet | Mittwoch, 23. Oktober 2019 21:50 (1571860222487) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001767830) |
Gesendet | Mittwoch, 23. Oktober 2019 21:52 (1571860363253) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001768075) |
Gesendet | Mittwoch, 23. Oktober 2019 21:52 (1571860374101) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001768154) |
Gesendet | Mittwoch, 23. Oktober 2019 21:53 (1571860391081) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001768319) |
Gesendet | Mittwoch, 23. Oktober 2019 21:53 (1571860415620) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001768420) |
Gesendet | Donnerstag, 24. Oktober 2019 00:06 (1571868415939) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001769923) |
Gesendet | Donnerstag, 24. Oktober 2019 00:07 (1571868437210) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001770146) |
Gesendet | Donnerstag, 24. Oktober 2019 00:07 (1571868451182) |
---|---|
Empfangen | Freitag, 25. Oktober 2019 13:09 (1572001770412) |
if needed new logs from B
for the messages after the out-of-order message:
https://debuglogs.org/566cf092614f215931f37c94b144bd6de6482a113f7b62701966f0a1e08aa17d
and from S
:
https://debuglogs.org/044ab5f6937889a185f084e79ef78a337c5cdee8ae300f3b9057ec9301a0a20d
@rainerzufall Thanks for that additional information. This still fits the scenario I described earlier:
INFO 2019-10-25T11:09:07.397Z queueing envelope +[REDACTED]453.6 1572001657763 (005a895c-6863-4c1e-ac12-be7f1ab30153)
INFO 2019-10-25T11:09:09.914Z message from +[REDACTED]453.6 1572001657763 (005a895c-6863-4c1e-ac12-be7f1ab30153)
INFO 2019-10-25T11:09:10.034Z sent message to +[REDACTED]442 1572001657763 from +[REDACTED]453.6 1572001657763 (005a895c-6863-4c1e-ac12-be7f1ab30153)
INFO 2019-10-25T11:09:21.817Z Starting handleDataMessage for message +[REDACTED]453.6 1572001657763 in conversation +[REDACTED]442
--- this is the message that should go before 1572001657763, queued 27 seconds afterwards
INFO 2019-10-25T11:09:34.026Z queueing envelope 31c666ca-efa5-4d5c-80ad-b59d2577cb6a
INFO 2019-10-25T11:09:41.688Z data message from +[REDACTED]442.1 1571997667768 (31c666ca-efa5-4d5c-80ad-b59d2577cb6a)
INFO 2019-10-25T11:09:50.056Z Starting handleDataMessage for message +[REDACTED]442.1 1571997667768 in conversation
The fact this is still open after 1.5 years, and new instances of the issue are being resolved as duplicates, makes me concerned this bug is being treated as if this is "operating as intended". Such a development mindset would certainly discourage me from further recommending Signal...
@rainerzufall Your scenario fits the pattern: loading a lot of messages at once, and some very recent messages are sorted older than they should be. We believe this to be a server issue; messages can jump the queue while Desktop is downloading older messages. This causes problems because, as always, Desktop sorts in the order it receives messages from the server.
@scottnonnenberg-signal This definitely happened to me just now, I had two new messages received while the desktop client was loading ~400 messages from the past two weeks, and the new ones got mixed in with the old ones in the wrong order.
The symptoms of the bug seem pretty clear. What's holding up a fix at this point? The messages all have timestamps, so it doesn't seem like it should be difficult for the desktop client to display them in chronological order.
I just started having this problem. On Android it appears to be in order but on desktop newer messages are moving up a conversation or two. Has there been any progress on fixing this?
I had this again.
It was a group chat message with 10 members. The message was misplaced in the past (8 hours before) on Win Desktop receiver side. On iOS mobile side the order was OK.
Phone numbers Sender: xxx377 Receiver: xxx759
Versions, logs Receiver: iOS 3.8.2.7 https://debuglogs.org/71e581cb9bad6e0f476be20fac5ebbd20af501461d31b08d3814b14155b4ad88.zip
Receiver Desktop app (Windows, 1.33.4) https://debuglogs.org/17fd68b89c281c78d9096845bd0ef80dc129ff31a9035a05d9cb3470a6076c63
Sender: from Win Desktop (linked with Android mobile device)
Timestamps Sent: 1588775949760 Received: 1588776219324
Log snippet
2020/05/06 16:39:11:494 💛 [OWSMessageDecrypter.m:203 -[OWSMessageDecrypter decryptEnvelope:envelopeData:successBlock:failureBlock:]]: decrypting envelope: <Envelope type: UnidentifiedSender, source: (null).0, timestamp: 1588775949760 content.length: 549 />
2020/05/06 16:39:11:497 [SessionCipher] [ REDACTED_PHONE_NUMBER:xxx377 ].2 creating new chains.
2020/05/06 16:39:11:498 [SessionState] Trimming excessive receivingChain count: 6
2
What is interesting The misplaced message was 8 minutes old when I opened the conversation and looked at it. The message was placed directly after an another normal (but old) message that was 8 hours old. I don't know is this relevant, maybe just coincidence.
message old1: "blah blah" - 8 hours ago message new-misplaced: "woof woof" - 8 minutes ago message old2: "hello world" - 8 hours ago
The known 'out-of-order' scenario is that Desktop, when downloading a lot of messages, can have a new message jump the queue. It looks like a couple of your newest messages nestled among old messages.
Here's my previous mention of that scenario: https://github.com/signalapp/Signal-Desktop/issues/2424#issuecomment-546509787
You can help us by telling us when your scenario seems to match what I've described, and when it doesn't.
Hi @scottnonnenberg-signal,
All right here are the preceding and the following messages at the RIGHT PLACE:
Message before the problematic one Sender: xxx270 Sent: 1588775730730 Received: 1588794113060
Message after the problematic one Sender: xxx270 (same person as "before" message above) Sent: 1588778934460 Received: 1588794115505
And here are the preceding and the following messages at the WRONG PLACE (in the past): Message before the problematic one Number: xxx164 Sent: 1588705197587 Received: 1588776218837
Message after the problematic one Number: xxx377 Sent: 1588746567030 Received: 1588776220006
Same problem...
Debug Log Mac OS: https://debuglogs.org/30d9a5ddb02ff35b61bc98726db5fc13e5ce2d1ba87c0f4f12f98f53da074ead Debug Log iOS: https://debuglogs.org/f981f44f1b67f1d07a7c8c5ea4fcd81bc61e2fb97e9e336ac4805b0ec9bfd983.zip
I was just thinking yesterday: could it be a timezone issue maybe? And maybe is it so hard to reproduce it for developers because they all are in the US...?
@kaktusztea - I live in the US, both phone and computer are in the same time zone, I've had this issue happen just like that.
As far as I can tell, the developers seem to be ignoring this as "by design", while they add support for annoying stickers.
Oh, and don't even get me started on forcing the user to choose a PIN, and then making you verify the PIN to make sure you remember it. The developers appear to be out of touch with the users.
Oh, and don't even get me started on forcing the user to choose a PIN, and then making you verify the PIN to make sure you remember it. The developers appear to be out of touch with the users.
While we are bitching - I just discovered that Signal on iPhone is the only messaging app among the ones my partner uses (vs. Signal, WhatsApp) that won't allow her to take her messages with her to a new phone number on another phone...
@amosshapira https://signal.org/blog/ios-device-transfer/
I have the same issue on multiple devices. Wrong order of messages is an absolute deal breaker for a chat app. This and the ridiculous time it takes to load the chat history even on high end mobile devices.
@beatschubser Have you reported your mobile performance issues? I'm sure the iOS or Android team would appreciate hearing about your scenario.
Using latest version of Windows and android apps, I just had a message show up out of sync. Message from an hour ago is showing up in between messages from 9 hours ago.
The problem with messages in wrong time order happens regularly for me. At first I thought some messages are missing, only to discover they are inserted somewhere earlier. Time varies, but it's not always just few minutes. This makes reading an conversation unpleasant and the meaning get's distorted.
If it's no easy fix please provide an option to order by time sent. The argument of overseen messages, that are inserted way back in the timeline might be solved by an indicator of unread messages (and possibility to jump to).
@strybe The more you can tell us about these scenarios, and in particular the situations surrounding the sends of those messages, the better. And of course a debug log with the 'sent id' of the messages (the number next to the 'sent' header in the message details screen). We can only make progress if we have information we can use to fuel the investigation.
Bug description
was chatting on mobile then open desktop app and messages show up out of order
Steps to reproduce
chat on ios mobile
open desktop app after chat
Actual result:
order of messages on desktop different than actual conversation and the messages were not super close together in time so it shouldn't be some "same time" issue
Expected result:
desktop message display order matches real order and order shown on ios
Screenshots
desktop - wrong order
ios - correct order where chat happened. last 4 messages
Platform info
Signal version:
1.11.0
Operating System:
osx
Linked device version:
Link to debug log
desktop https://debuglogs.org/03fa13400a56d08ba585e0771e76d4c639d1e9cef7522ebbe2557b05bc68d00e
ios https://debuglogs.org/fe78834c9bdaceec0101a3e2ab192f47f46204c4482e308e2ef5067d93c8d4ac.zip