Conversations in left pane sorted incorrectly after new message arrives

[jeremymasters]

After update to android 4.9.9, message sorting is not popping groups to the top when a group message arrives.

I have group messages that arrive but the desktop app doesn't re-sort the list to have that group on the top of the list of my threads on the desktop app. Android app has sorting done correctly.

STR:

1. get message from 1:1 thread
2. get message from group thread

Notice the group doesn't move up to the top of the list in the desktop app.
Note: restarting the Signal Desktop app sorts properly.

version 0.42.6:
https://gist.github.com/635088e404dc4896500f0e73871ad367

[jeremymasters]

[scottnonnenberg]

Hi there, Jeremy. You've entered an Android bug in the Desktop repository! Please enter this bug in the Android repository here: https://github.com/WhisperSystems/Signal-Android/issues

[jeremymasters]

@scottnonnenberg Sorry, I didn't realize such since it wasn't manifested in my Android client! Also, after the restart of the desktop client, it seems to be working fine again?

[michaelkirk]

I think the confusion was that you started your bug report with "After update to android 4.9.9, message sorting is not popping groups to the top when a group message arrives."

So you're saying after updating your Android device, your desktop sorting seemed broken?

[jeremymasters]

@michaelkirk yeah, I should have said "Signal Desktop problem after upgrading blah blah blah" or some such. Anyway, yeah, I was using Android 4.9.8 + signal desktop for a few days (Mon-Wed) and then last night upgraded to 4.9.9 and this morning there were a couple cases where the new message coming in would show, but wouldn't re-sort the list to put it at the top, like in the picture. I restarted the desktop client once and that re-sorted, but I had to do it again. Now it seems to be solved but we'll see.

[jeremymasters]

started doing it again: https://gist.github.com/f9d5014fa9004bee82bcb1da18517cbf

[jeremymasters]

Android log after: https://gist.github.com/afd9d141e8b80d5c447e05e227ce74f7

[jeremymasters]

Maybe you guys can sort out which module is at fault with those two logs.

[scottnonnenberg]

Hey there. I just tested sending and receiving group messages with Android 4.9.9 and the latest Desktop, and I'm not seeing any strange sorting behavior. I also didn't see anything strange in your provided desktop log.

Can you tell us a little bit more about when the problem manifests? Which messages seem to have problems with sorting, and which sort properly? For example, is it other people sending messages to the group, or your messages sent with Android to the group which are then sync'd to Desktop?

[jeremymasters]

I thought it was only groups, but it was to a group and then also to someone with whom I had 1:1 conversation with 1 day expiring messages. It's always when a message is sent to me.

[scottnonnenberg]

Hm. I don't think we have enough information to move forward.

The next time a message comes in that doesn't result in a proper re-sort, can you submit a debug log and let us know what phone number the message came from? Or, if you can remember which messages came in and didn't sort properly, that would help us analyze the log you already provided.

[michaelkirk]

@jeremymasters - have you noticed if it's always from the same sender? And if so, can you find out if their clock is set properly?

[jeremymasters]

@michaelkirk two different senders, one iOS and one Android. Neither has messed with their clock at all. Phone numbers ending in 05 and 76

[scottnonnenberg]

@jeremymasters What happens if you send a message to those improperly-sorted conversations? Do they then move to the top?

[jeremymasters]

Yes

[jeremymasters]

This time I sent a message to "orange user" and it didn't update the sorting:
https://gist.github.com/aabeaa8e24dc03358d7e97d8e462a05c

[scottnonnenberg]

I've inspected the code in question, and there's no smoking gun. I wonder if there's an error not being reported in the logs. You can get at the real-time logs by going to chrome://extensions, finding Signal Desktop, then clicking the background.html link to open the DevTools. Once there, take a look at the Console tab - maybe some errors are popping up? Or at least some things not present in the official log?

[jeremymasters]

components.js:23719 Deprecation warning: moment construction falls back to js Date. This is discouraged and will be removed in upcoming major release. Please refer to http://momentjs.com/guides/#/warnings/js-date/ for more info.
Arguments: [object Object]
Error
    at Function.createFromInputFallback (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:23731:105)
    at configFromString (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:25461:32)
    at configFromInput (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:25821:13)
    at prepareConfig (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:25804:13)
    at createFromConfig (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:25771:44)
    at createLocalOrUTC (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:25858:16)
    at local__createLocal (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:25862:16)
    at utils_hooks__hooks (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/components.js:23462:29)
    at child.getRelativeTimeSpanString (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/views/timestamp_view.js:48:29)
    at child.update (chrome-extension://bikioccmkafdpakkkcpdbppfkghcmihk/js/views/timestamp_view.js:31:31)
warn @ components.js:23719
debugLog.js:49 websocket open
debugLog.js:49 got request PUT /api/v1/queue/empty
debugLog.js:49 MessageReceiver: emitting 'empty' event

[scottnonnenberg]

@jeremymasters Okay, I have a theory. One or more of your conversations have a non-date timestamp, and it's causing sorting to go wacky. We should be able to tell which one by restarting the app and looking for the conversation with the newest date. And you should be able to fix it by sending a message to that conversation.

I'm still trying to figure out what might cause a timestamp to be set with a non-date. :0/ Maybe if you find it, you can tell me what has happened with the conversation recently.

[jeremymasters]

@scottnonnenberg Thanks for hanging tough on this one. I'll be of as much help as humanly possible. It happened again this morning, but this time, I sent a message to one of my most frequently messaged contacts and it sent the message from one of the top two spots, down about 7 or 8 spots. Restarting the app, sorted things correctly again.

[scottnonnenberg]

If you look at the timestamp for all conversations, do any of them look off?

[jeremymasters]

In looking at the the app shows what looks to be correct times, even when they are out of order. I don't know where to look in the dev console to look at actual timestamp values.

[jeremymasters]

This is after the restart. Forgot to send before. :(
https://gist.github.com/38358e4c0d55317e4b4664a0640b77b9

Line 2040 certainly looks a little weird:
2017-08-28T17:49:21.869Z Conversation «� ª¯N¯cÒ¦jMG�W& took 2054 milliseconds to load

[jeremymasters]

And there seem to be tons of delivery receipts that are junk? Haven't received a message in almost 2 hours but all those receipts linger.

[jeremymasters]

Happened again..this time I received the message. This log probably has some overlap, but I captured it almost immediately after it happened. Message arrived, did not bubble to top of desktop list but did bubble to top in android client. I frequently message this contact as well...ending in 776.
https://gist.github.com/anonymous/417110fda14f85b5e28339c1ec701063

Received a second message right after this while i was still typing this out and the thread popped to the top now upon receipt of second message.
https://gist.github.com/anonymous/b27e58ab2c1f2c99ccce3a3e0a60221a

[deutrino]

This still happens on rare occasion in Electron. I'm on 1.0.34 but have seen it a couple other times, and in fact think there was maybe a different ticket regarding this which may have had a fix committed and been closed, if memory serves, but I can't find it now.

I've only noticed this on messages I've received. Once I send a message in the conversation, it pops to the top. Here's an example which I didn't notice until 19 hours later. I didn't notice if this was out of sort order on Android after 19 hours, but it was working normally while I had exchanged messages with other contacts just a few hours after receiving and not looking at the messages in the conversation in question. Number is **227. Message timestamps appear correct in the conversation view and also when clicking for more detail.

Also, of the 3 unread messages, one was received several hours before the next two, so that's why only two will appear in the logs ~19 hours before the end.

https://gist.github.com/deutrino/b0dba58062013523c0c2c606dab74994

I'm also wondering if there is any relation to #812.