GNOME Bugzilla – Bug 713190
Conversation list mis-sorts when new email arrives
Last modified: 2021-07-05 13:24:28 UTC
---- Reported by rschroll@gmail.com 2013-05-21 17:38:00 -0700 ---- Original Redmine bug id: 6981 Original URL: http://redmine.yorba.org/issues/6981 Searchable id: yorba-bug-6981 Original author: Robert Schroll Original description: Sometimes when I get new email, one or more of the conversations may get mis- ordered in the conversation list. I think it only happens when I get several new messages in a few conversations, but other than that, I haven't found a rhyme or reason to which cause the problem. Although the date displayed in the preview is correct, the conversation is too early. On several occasions, I've noticed it was about 12 hours early, which makes me wonder if there's an AM/PM issue, but it's not exactly 12h off. Switching to another folder and back is enough to get the list sorted correctly. Is there any diagnostic to do when I notice it happening that would help? ---- Additional Comments From geary-maint@gnome.bugs 2013-09-04 13:20:00 -0700 ---- ### History #### #1 Updated by Jim Nelson 6 months ago Curious, I don't know that I've seen this. I've been on the lookout for it on my end but haven't encountered it. As far as a diagnostic, I think the best thing you could do when you see it is to look at every email in the conversation and take note of the Date: field. Does the Date in the conversation list correspond to the last message? (I know it can be hard to tell if the message was not from the current day.) Are the messages in date order in the conversation viewer? Another thing to look at is the debug output. I don't know exactly what you should be looking for, but anything that indicates that a message was unable to be added/appended/refresh a conversation. Finally, do you get notifications for these messages when this occurs? #### #2 Updated by Robert Schroll 6 months ago Here's what I see currently. (Apparently, I haven't changed folders in two days.) The first line of the group is the time displayed in the conversation list and the following are the times reported in the conversation views. You can see that the times are apparently all correct. 5:12 pm May 18, 2013 1:09 pm May 18, 2013 5:08 pm May 18, 2013 5:10 pm May 18, 2013 5:11 pm May 21, 2013 5:12 pm 2:59 pm May 21, 2013 2:59 pm [3 other conversations] 11:52 am May 19, 2013 3:32 pm May 20, 2013 11:43 am May 21, 2013 11:52 am 4:28 pm May 18, 2013 12:44 pm May 20, 2013 2:18 am May 21, 2013 4:27 pm May 21, 2013 4:28 pm 3:26 pm May 20, 2013 11:43 pm May 21, 2013 3:26 pm 3:48 am May 21, 2013 3:48 am (In case it's not immediately obvious, the problem is the second and third conversations from the end.) These messages arrived with some others that were sorted correctly. I'd guess that all the emails 11:52 am and after arrived as a bunch. I don't remember a notification; Geary probably had focus at the time. The logs are long gone, but I'll grab them the next time I see this. I can't believe this is related, but the 2:59 pm message (right before where the conversations should have sorted) was a reply to the 11:52 am conversation (right after where they did get sorted). But it's lacking a References header, which I presume is the reason it's on its own. #### #3 Updated by Jim Nelson 6 months ago * **Status** changed from _Open_ to _Review_ * **Assignee** set to _Jim Nelson_ * **Target version** set to _0.4.0_ Looking at the code, my hunch is that in the case of the errant conversations, they were updated with new emails but not re-sorted ("refreshed" in the lingo of ConversationListStore). It turns out there's a few ways this could happen, but in every case a warning message is dumped to the console. In general, these conditions are red-alarm bugs, such as ConversationMonitor saying a conversation had an email added to it but the ConversationListStore has no record of it; stuff that's a bigger issue than what you're describing. In ConversationListStore.refresh_conversation(), there is a code path that's suspect here. If get_message_data_at_iter() returns null **or** the preview email has changed (which is what will happen when a new message arrives), it calls set_row(). That should re-sort the conversation. The `else if` is if message data is non-null and the number of messages it holds is not equal to the conversations, the "row-changed" signal is fired. This is the heart of the method; row-changed is supposed to trigger a re-sort without an insert, but it does require the number of messages to have changed. I'm wondering if this second test is required, perhaps the UI shouldn't be so clever and simply re-sort the row every time. I'm not exactly sure what sequence of steps would cause this situation to happen, but I can imagine one: you archive a message on one client (say, your phone) and another message in that conversation come in at approximately the same time. Sounds far-fetched, but we've seen similar timing issues in the past. I'm uploading a patch to `bug/6981-resort` that changes ConversationListStore to re-sort for any appended-message notification. Could you try running from it for a few days and see if it fixes this problem? #### #4 Updated by Robert Schroll 6 months ago * **File** missort.log added The good news is I can give you a prompt answer on whether it works. The bad news, as you probably have guessed, is that this answer is no. Ironically enough, it was the message from the above update that was mis-sorted. I didn't see any obvious problems in the debug log, but I'm attaching it here for you to take a gander at. It happened right as I opened (the newly compiled) Geary, so there's a lot of noise from everything happening all at once. There were 8 newly-arrived emails at the time. This comment will trigger another message to the conversation. I suspect this will cause a resort, but I'll edit this to let you know for sure. _ Edit:_ The conversation is now correctly sorted, after the arrival of the new email. #### #5 Updated by Jim Nelson 6 months ago * **Status** changed from _Review_ to _Open_ Hmmm ... ok, thanks. Need to think about this some more. #### #6 Updated by Jim Nelson 3 months ago * **Assignee** deleted (<strike>_Jim Nelson_</strike>) #### #7 Updated by Jim Nelson 3 months ago * **Target version** changed from _0.4.0_ to _0.5.0_ --- Bug imported by chaz@yorba.org 2013-11-21 20:19 UTC --- This bug was previously known as _bug_ 6981 at http://redmine.yorba.org/show_bug.cgi?id=6981 Imported an attachment (id=260605) Unknown milestone "unknown in product geary. Setting to default milestone for this product, "---". Setting qa contact to the default for this product. This bug either had no qa contact or an invalid one. Resolution set on an open status. Dropping resolution
This branch has been moved to wip/713190-resort with the move to GNOME.
For the record, this is still happening regularly.
Darn. I wish we'd looked at this when you were here. The branch is, of course, quite old and merging with master is probably painful at this point. Let's keep it for now, just so I remember what I was trying to do that didn't work and don't go down that path again. Something I noticed, looking at this with fresh eyes: compare_conversation_ascending() in util-email.vala does a straight comparison of the latest email's date received. Technically that can lead to two conversations with their latest emails having the same received time comparing as equal. That's incorrect; we need something to stabilize the sort. Since IMAP's received time (INTERNALDATE) has second accuracy, this isn't such an edge case. Since you're seeing this a lot, one thing you might try is stabilizing the sort there, i.e. if the date_received compare returns zero, use Geary.EmailIdentifier.stable_sort_comparator. That's exactly why we coded that, for this kind of situation.
Created attachment 294824 [details] Logs Got it happening again. Here's the logs. Screenshots demonstrating the mis-sort will follow.
Created attachment 294825 [details] Conversation list. All of today's email was loaded into Geary at this time.
Created attachment 294827 [details] Conversation list. A single conversation was mis-sorted.
Created attachment 295063 [details] Logs Here's the evidence from another case I caught. I'd only been using my phone for some time, so I got a bunch in together. This time it mis-sorted twice, which I don't think I've seen before. If we've reached the limit on helpfulness here, let me know. Otherwise, I'll keep posting these as I see them.
Created attachment 295064 [details] Upper sort problem
Created attachment 295065 [details] Lower sort problem
Yeah, I don't think adding more logs or screenshots are going to help any. No need to spend time doing so, unless you think there's something in them that's different than before. It is interesting that your latest log shows 41 new messages coming into your Inbox. I don't see anything in the log indicative of the issue. Let me look at the code again and see if I can add some debug log that might help...if only I knew where in the code was the problem! Let me take a look at this and see what I can do. There's a couple of nits in the code we discussed last week I'd like to fix, although I don't know they're going to solve your problem.
Robert, I've created branch wip/713190-resort-2. If you could run out of that for a few days and see if the problem persists, that would be a huge help. The branch does a number of Big Things: * Before, code in the client and engine was loose when discussing sorting by date. Now the code is explicit, it's either sorting by sent date (the Date: header) or the received date (IMAP's INTERNALDATE). This is complicated by the ConversationListStore sorting by received date and the ConversationViewer sorting by sent date, but so be it. * I firmed up all the email date comparators to fall back on the EmailIdentifier as a sort stabilizer. I can't point exactly where this might be causing the problem, but it's something we should be doing. * Added some explicit logging to the comparators whenever they have to fall back on EmailIdentifiers (i.e. it's not sorting by date) to make sure that's not tripping us up. * Ensure that a "row-changed" signal is being fired whenever a conversation is updated. Looking at GtkListStore, it's not guaranteed to happen (but, if I'm reading the code correctly, will in our case -- it's not obvious, though). * ConversationListStore used to walk the list to look up Conversation -> Gtk.TreeIter, an O(n) search that has always bugged me. I moved that to a HashMap lookup. This won't fix the problem, but I was in the code and decided to jump on it. None of these explicitly fix the problem, but without really knowing what that might be, I'm hoping they will either squash it or eliminate possibilities to then know we need to look elsewhere.
I've been running this branch since Thursday, and I haven't noticed a mis-sort yet. I'm hope that this has solved it for some unknown reason, but I'll keep running it for a while to be sure. I haven't noticed any other problems with the branch, so it may be worth merging it even before we're 99% sure it fixes things.
Created attachment 295552 [details] Screenshot showing lack of update of conversation date Of course, as soon as I say that, I see a new mis-sort. I'm not sure that this is the same problem, though. It involved the arrival of a single new message, which I've never noticed mis-sorting before. This was put in an existing conversation, but that conversation did not have its time updated, and the conversation was placed correctly by the second-newest message, where it should have been before the new message arrived. (The screenshot was taken around 3am on the 27th.) This looks to me like the conversation didn't get the date updated correctly, rather than the other examples here.
Created attachment 295553 [details] Log showing lack of update of conversation date
You're right, this doesn't look like the same problem. As I mentioned, a complicating factor here is that the conversation list is sorted by date received while the conversation viewer sorts by date sent. It gets more problematic because both views display their "preferred" date, which means it's possible to get disconnects in the user interface. If you go into your database, can you find the email in the MessageTable? I'm specifically interested in its internaldate. We need to know that to be sure of what's going on here. (It might be smart to find a way in-app to get that information. We have a ticket for tooltips in the conversation list, that might be one thing worth putting in them.) If you switch folders or restart Geary, did the conversation sort correctly? I can't tell from your description (and the blacked-out email) if the conversation was mis-sorted when the message arrived.
That conversation is correct sorted based on the time of the penultimate email. I assume when the last email came in, it got sorted into the conversation, but the conversation never updated its time, and so it stayed in the same place. After switching folders, the conversation sorted correctly. The internal date seems to be correct. It's set to "27-Jan-2015 07:40:33 +0000", which is just a few seconds after when the email thought it was sent ("Tue, 27 Jan 2015 14:40:12 +0700") and, if I did the time zones correctly, when I noticed it arrive. The emails in the conversations before and after, as well as the previous one in this conversation, all have internal dates of "26-Jan-2015 23:XX:XX +0000".
Ok. While this looks different, it's kinda-sorta related. I merged master into the resort-2 branch and pushed one more change. Now when a conversation is refreshed (due to messages being added or removed, among other reasons), we simply replace the ConversationListStore element with a new one. There was some code in there that I think was attempting to shave a few cycles, but ultimately I'm unconvinced that (a) "row-changed" is sufficient to re-sort the element and (b) the cycle-shaving may have prevented the element from updating. So, what I'm asking is, can you run this branch for a while longer and see if you see this problem again.
I just saw the new-style mis-sort again. This time, I was loading a bunch of messages. All but one conversation got placed correctly, but one didn't get the new time assigned correctly. Switching folders and going back was enough to get it sorted correctly.
And I just saw a traditional mis-sort. Nuts.
Crud. I'm out of ideas at this point. I just don't see where the problem could be (in the branch). I may merge the branch anyway, as I think there are some nice improvements in it. One idea you might try: * Create a new folder (to avoid dirtying up Inbox) * Open that folder in Geary * In a threaded client (i.e. Thunderbird), copy into the new folder individual messages of larger threaded conversations. Try to move a number of messages at once. Are they sorted correctly? * Then move in more messages from All Mail into that folder. Are they still sorted correctly?
I feel like it's sorting correctly more often on this branch, though I've no hard data to back that up. I may play with your folder idea in a bit, but right now, I'm tired of messing with this.
> I may play with your folder idea in a bit, but right now, I'm tired of messing > with this. Understood. I can't blame you. I've merged the second branch into master, commit e52652. I've deleted that branch and the original one, to reduce clutter.
This just happened to me. Importantly, this occurred while running wip/713150-conversations, which touches ConversationMonitor (a lot) and ConversationListStore (a little). In descending order (i.e. just like the list, top to bottom): A: A conversation with 7 total messages, two new ones: (bug #732844) CLS reports "23m ago", i.e. 11:55am New: 10:03am (UID 111461 / rowid 105191 / sent 17:03:17 / recvd 17:03:24) New: 11:55am (UID 111464 / rowid 105197 / sent 18:55:37 / recvd 18:55:51) B: A new conversation (1 message), new arrived: (bug #746472) CLS reports "2h ago", i.e. 10:13am New: 10:13am (UID 111462 / rowid 105192 / sent 17:13:02 / recvd 17:13:10) C: A conversation with 3 total messages, two new ones: (bug #741512) CLS reports "23m ago", i.e. 11:55am New: 10:00am (UID 111460 / rowid 105190 / sent 17:00:15 / recvd 17:00:20) New: 11:55am (UID 111463 / rowid 105196 / sent 18:55:37 / recvd 18:55:48) All sent and recvd dates (i.e. Date:, INTERNALDATE) are UTC. In other words, the ConversationListStore is reporting the correct time of the latest message in the conversation but they're sorted incorrectly in the list: 11:55am, 10:13am, 11:55am. What's interesting here is that the first and last conversations were related tickets from Bugzilla: one newest email was a report that the ticket was a duplicate of another ticket, and the other newest email was a report that the ticket had a duplicate. There are no equal recv dates, they all should compare without having to resort to a sort stabilizer. But there are two equal sent dates (18:55:37), and I have to wonder if that's screwing up the sort. The sort stabilizer for either date is the UID. This is also frustrating, because they're not sorted by latest UID. If the UID is the same (which shouldn't happen, but a comparator isn't a good place to assert), we fall back on the SQLite rowid: but it's not sorted by that either. Also note that conversation A was re-sorted compared to B (i.e. it moved, or should have moved, when the second email arrived). C did not re-sort correctly. Why? Let me look at this some more.
Looking back at my debug log, I see that the two suspect messages arrived at the same time: [deb] 11:56:02 92.832917 imap-folder.vala:194: INBOX EXISTS 164 [deb] 11:56:02 0.000360 imap-engine-minimal-folder.vala:1070: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) on_remote_appended: remote_count=162 reported_remote_count=164 [deb] 11:56:03 1.000816 imap-engine-replay-queue.vala:218: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true): Scheduling 1 held server notification operations [deb] 11:56:03 0.000352 imap-engine-minimal-folder.vala:1104: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) do_replay_appended_message: current remote_count=164 reported_remote_count=164 remote_positions=( 163 164 ) [deb] 11:56:03 0.250194 imap-engine-minimal-folder.vala:1118: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) do_replay_appended_message: 2 new messages in pos::163,164 [deb] 11:56:03 0.009000 imap-engine-minimal-folder.vala:1128: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) do_replay_appended_message: appended email ID [105196/111463] added [deb] 11:56:03 0.000018 imap-engine-minimal-folder.vala:1128: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) do_replay_appended_message: appended email ID [105197/111464] added [deb] 11:56:03 0.007408 imap-engine-email-prefetcher.vala:131: Listing new 2 emails needing prefetching in Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true)... [deb] 11:56:03 0.000519 imap-engine-minimal-folder.vala:1166: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) do_replay_appended_message: completed, current remote_count=164 reported_remote_count=164 (A) [deb] 11:56:03 0.000762 app-conversation-monitor.vala:790: 2 out of folder message(s) appended to Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true), fetching to add to conversations... (B) [deb] 11:56:03 0.006626 app-conversation-monitor.vala:720: 2 message(s) appended to Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true), fetching to add to conversations... [deb] 11:56:03 0.000266 imap-engine-email-prefetcher.vala:135: Listed new emails needing prefetching in Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) [deb] 11:56:03 0.000016 imap-engine-email-prefetcher.vala:94: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true): scheduling 2 emails for prefetching [deb] 11:56:03 0.346469 unity-launcher.vala:44: set unity launcher entry count to 7 [deb] 11:56:03 0.024448 new-messages-monitor.vala:145: do_process_new_email: 2 messages listed, 7 unread in folder Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) [deb] 11:56:04 0.382092 imap-engine-generic-account.vala:349: Refreshing unseen counts for Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) [deb] 11:56:04 0.000184 imap-engine-email-prefetcher.vala:175: do_prefetch_batch_async Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) start_total=2 (C) [deb] 11:56:04 0.000072 imap-engine-email-prefetcher.vala:230: do_prefetch_email_async: Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) prefetching 2 emails (11160b) [deb] 11:56:04 0.433184 app-conversation-monitor.vala:790: 2 out of folder message(s) appended to Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true), fetching to add to conversations... [deb] 11:56:04 0.003778 imap-engine-email-prefetcher.vala:225: finished do_prefetch_batch_async Gmail:jim@yorba.org:INBOX (open_count=2 remote_opened=true) end_total=2 105196/111463 is: 11:55am (UID 111463 / rowid 105196 / sent 18:55:37 / recvd 18:55:48) 105197/111464 is: 11:55am (UID 111464 / rowid 105197 / sent 18:55:37 / recvd 18:55:51) Something important to note from the log: (A) and (B) show two signals being caught by the ConversationMonitor: first those two messages are treated as "out-of-folder" even though they arrived in the Inbox, then they're reported as appended to the Inbox. This could be problematic, because the CLS sorts by date received of messages *in the folder*. If one or both of those emails are considered to be "out of folder" due to this ordering problem, that could lead to a sorting problem. However, the CM is designed for the problem; adding emails twice to it is caught and handled. What's more, although the first signal is an "external append", it's reporting the append as happening in Inbox, which is accurate. Later, the two new emails are detected in All Mail: [deb] 11:56:16 0.000241 app-conversation-monitor.vala:790: 2 out of folder message(s) appended to Gmail:jim@yorba.org:[Gmail]/All Mail (open_count=1 remote_opened=true), fetching to add to conversations... The CM *should* drop those. Unfortunately, I don't know if the ConversationList mis-sorted when they first landed in the Inbox or after 12 seconds, when they were detected in All Mail, i.e. "out of folder". It's the CM's responsibility to add newly-discovered paths to the Conversation object, so this is interesting too. Also, code path (A) assumes all the required information is stored in the database and there's no issue loading all the information it needs (even though only a partial database row has been downloaded). (B) will force the necessary information to be downloaded from the server before listing it from the database. (We can do that because in B the folder is guaranteed to be held open by the ConversationMonitor.) Only after A and B does the email prefetcher kick in to download the entire email (C). That said, the date received is among the first metadata downloaded from the server when a new email is detected, so I'm hesitant to give it too much credence.
Finally this happens to someone else!
One more data point: the conversation list sort is triggered by the "conversation-appended" signal from the ConversationMonitor. If that signal is not fired, the item will not be re-sorted. The date in the conversation list (which was accurate for me) is not triggered by a signal. Instead, there's a background polling loop which updates it one a minute (which is how it updates over time). So, one possibility is that the email was added to the conversation but the appended signal was not fired (or, it was fired when the email was first added but with the wrong or incomplete paths and treated as "out-of-folder" but not later when the "in-folder" path was added). Just talking out loud here. I've been up and down the sorting code until my eyes bleed. I wonder if the sort is simply not being triggered in a corner case.
GNOME is going to shut down bugzilla.gnome.org in favor of gitlab.gnome.org. As part of that, we are mass-closing older open tickets in bugzilla.gnome.org which have not seen updates for a longer time (resources are unfortunately quite limited so not every ticket can get handled). If you can still reproduce the situation described in this ticket in a recent and supported software version, then please follow https://wiki.gnome.org/GettingInTouch/BugReportingGuidelines and create a new ticket at https://gitlab.gnome.org/GNOME/geary/-/issues/ Thank you for your understanding and your help.