1135588 - New conversations get indexed twice by gloda, leading to duplicate search results

Status: RESOLVED FIXED

(Thunderbird :: Instant Messaging, defect)

Description

[aleth [:aleth]]

STR
Start a conversation
Say something (X)
Close the conversation (context menu of the sidebar)
Run a search for X: Everything looks good, a result for X appears.
Now close and restart TB.
Run a search for X: The result for X appears twice.

Looks like the file is indexed again on restart, so some flag isn't getting set?

Comment 1

[Kent James (:rkent)]

What is the plan to move forward with this?

Comment 2

[(inactive) Nihanth Subramanya [:nhnt11]]

There has been some progress on this. Some debugging has revealed that the source of the bug is a timer that is never reset. Seems like the issue has been around since chat landed in Tb. I'll be working on this and bug 1135291 this weekend and through next week.

Comment 3

[(inactive) Nihanth Subramanya [:nhnt11]]

Attachment: Patch

I haven't tested this yet, clobber build running at the moment.

Comment 4

[aleth [:aleth]]

I remember testing this and it seemed a shutdown handler was required here so pending saves are ensured to haopen.

Comment 5

[aleth [:aleth]]

Attachment: cachesave.diff

Since I'd already discussed this with nhnt11, it seemed easy to finish this patch so nhnt11 can focus on the chat reindexing bug.

Comment 6

[aleth [:aleth]]

Not actually a regression - this bug has existed since gloda IM indexing was added.

Comment 7

[aleth [:aleth]]

Attachment: cachesave.diff v2

I guess we should cancel the timeout too, just in case, though I don't think they fire any more at that stage in the shutdown.

Comment 8

[aleth [:aleth]]

Comment on attachment 8578896 [details] [diff] [review]
cachesave.diff v2

This won't do as _saveCacheNow uses NetUtil.asyncCopy.

Comment 9

[aleth [:aleth]]

Attachment: cachesave.diff v3

Apart from having to convert the save to OS.File so the shutdown blocker could wait upon its completion, there was another bug causing duplicates: if autojoined channels exist, the first save is scheduled on startup before the existing cache file has been read. If this save overwrites the cache file, we end up with duplicate entries in the gloda index.

Comment 10

[Patrick Cloke [:clokep]]

Comment on attachment 8578982 [details] [diff] [review]
cachesave.diff v3

Review of attachment 8578982 [details] [diff] [review]:
-----------------------------------------------------------------

This looks good! I wrote a couple of nits asking for more comments. :) I'm going to do a build and test this now.

::: mail/components/im/modules/index_im.js
@@ +268,3 @@
>        return;
>      this._cacheSaveTimer = setTimeout(this._saveCacheNow, 5000);
> +    if (this._shutdownBlockerAdded)

Nit: Add an empty line here and add a comment about what this is doing?

@@ +285,5 @@
>        knownFiles: GlodaIMIndexer._knownFiles,
>        datastoreID: Gloda.datastoreID,
>      };
>  
> +    let path = OS.Path.join(OS.Constants.Path.profileDir, "logs", kCacheFileName);

Keep the comment "Asynchronously copy the data to the file." :)

Comment 11

[aleth [:aleth]]

Attachment: cachesave.diff v4

adds comments!

Comment 12

[Patrick Cloke [:clokep]]

Comment on attachment 8579020 [details] [diff] [review]
cachesave.diff v4

I was able to still get duplicated indices with this. aleth was able to reproduce and has some ideas.

Comment 13

[aleth [:aleth]]

Attachment: glodafix.diff v5

This was a little tricky to debug.
First I fixed
* autojoined channels got added to the cache before the cache was read from disk (which happened together with the log sweeping), which overwrote these new entries so they go missing
* cache save should work when there is no existing file
* we were receiving every new-text notification twice, scheduling twice as many indexing jobs as needed
* some minor inconsistencies which didn't really matter
but the problem was still there. It turned out to be a consequence of lastModifiedTime not being set on the indexing jobs of newly opened conversations (as opposed to old conversations found on log sweep). This led to weird behaviour and duplicates because if you set obj.property = undefined, hasOwnProperty.call(obj, "property") is true, but !!obj.property is false, and JSON.stringify(obj) doesn't include property at all. That way you could get conversations that were indexed but only sometimes found in the cache, and they would disappear on save.

Comment 14

[(inactive) Nihanth Subramanya [:nhnt11]]

I looked over this and it seems sane. Fixes the issue on my build.
Thanks a ton for taking over this messy bug!

Comment 15

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/5ec38389ad9a

Comment 16

[aleth [:aleth]]

Comment on attachment 8580304 [details] [diff] [review]
glodafix.diff v5

[Approval Request Comment]
Regression caused by (bug #): 955292, plus longstanding bugs

Comment 17

[Kent James (:rkent)]

Comment on attachment 8580304 [details] [diff] [review]
glodafix.diff v5

https://hg.mozilla.org/releases/comm-aurora/rev/08f97de69ea3