783022 - After the initial message, conversations are not indexed or searchable until TB is restarted

Status: RESOLVED FIXED

(Thunderbird :: Instant Messaging, defect)

Description

[Mike Conley (:mconley) (:⚙️)]

STR:

1) Create an IRC account in TB, and join an empty channel
2) On a separate client, join the same channel
3) Chat with yourself, using words that are easy to search for.
4) Upon receiving the first message from the non-TB client, note that you can search for that message

What happens?

Subsequent messages do not appear in search results until *after* TB is restarted.

What's expected?

The messages should be indexed soon after the user sees them, and then immediately searchable without a restart.

I'm not sure if my STR are accurate - I'm still feeling this one out.

Comment 1

[Mike Conley (:mconley) (:⚙️)]

I'm experiencing this in the latest beta, and on a trunk build.

Comment 2

[Mike Conley (:mconley) (:⚙️)]

This bug appears to be in TB Beta build 2 as well, so this doesn't appear to be caused by the deferred Gloda indexing work I did.

Comment 3

[Mike Conley (:mconley) (:⚙️)]

Hm, so far, I'm only able to reproduce this on my Windows machine. My Linux box seems to be working fine, which makes me wonder if something's gone wrong with my Gloda index, or perhaps my IM logs...

I'll try a new profile.

Comment 4

[Mike Conley (:mconley) (:⚙️)]

Ok, I think I figured this one out.

Our IM indexer caches and compares the last modified time for each log file in order to know whether or not to re-index a log file.

The indexer does this by holding a reference to the known log files, and simply checking nsIFile.lastModifiedTime.

The problem seems to be that on Windows, the lastModifiedTime is cached at the point where the nsIFile is instantiated...whereas on Linux (and maybe OSX, I didn't check), lastModifiedTime is updated dynamically.

That means that on Windows, the lastModifiedTime never changed from the point where we first made a reference to the file, so TB thought that the logs weren't changing, and so it wasn't re-indexing the files.

My solution is to "refresh" our reference to the log files at the point of starting an index job by using nsIFile.clone. This is the workaround that rkent suggested. He's also familiar with this Gecko lastModifiedTime bug, so he might be able to answer any questions about what that's all about. I've Cc'd him.

Patch up in a minute.

Comment 5

[Mike Conley (:mconley) (:⚙️)]

Attachment: Patch v1

This fixes things on Windows for me.

Comment 6

[Blake Winton (:bwinton) (:☕️)]

Comment on attachment 652206 [details] [diff] [review]
Patch v1

So, I've got two problems with this patch.

a) It's not a patch.
b) even if it was, I am in no way qualified to review this change.

r-.

Thanks,
Blake.  ;)

Comment 7

[Mike Conley (:mconley) (:⚙️)]

Attachment: Patch v2

A for-reals patch now.

Comment 8

[Mike Conley (:mconley) (:⚙️)]

Just a note, I talked to bbondy in #windev about the inconsistency, and he acknowledged it (nsLocalFileWin.cpp stashes the lastModifiedTime and fileSize at instantiation), and said that using clone() is a fine workaround.

Comment 9

[Andrew Sutherland [:asuth] (he/him)]

Comment on attachment 652208 [details] [diff] [review]
Patch v2

r=asuth with the understanding that the best-suited reviewer is on vacation.

Karma points are at risk for making main thread I/O more I/O'y (albeit in the name of correctness)!

Comment 10

[Mark Banner (:standard8)]

As an additional data point, I remember getting a patch like this from David on a bug previously, although I can't find the instance of it at the moment.

Comment 11

[Mike Conley (:mconley) (:⚙️)]

comm-central: https://hg.mozilla.org/comm-central/rev/9a13835a35c7

Comment 12

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 652208 [details] [diff] [review]
Patch v2

Hm. So I could have sworn this patch worked...but today's Daily (which contains the patch) is still not indexing my IM's as they come in.

What's more, these messages are not being indexed even after a restart.

Starting investigation...

Comment 13

[Mike Conley (:mconley) (:⚙️)]

Backed out patch on comm-central for now until I can figure out what's going on:

https://hg.mozilla.org/comm-central/rev/aba9ee720457

Comment 14

[Mike Conley (:mconley) (:⚙️)]

The problem is sporadic, and seems to (again) be related to lastModifiedTime.

It *appears* as if NTFS doesn't update lastModifiedTime immediately on file-write...I think it lazily writes it after some period, and *sometimes* that period falls outside of the point when our indexer kicks off, meaning that the doesn't look like it was modified.

I'm not too familiar with the inner workings of NTFS to know if what I'm saying is true, but it's what *appears* to be happening.

The (kind of) good news is that this behaviour is sporadic, and the messages *should* get re-indexed when the conversation is modified and lastModifiedTime is updated, or on restart.

I'm still convinced that we're doing the right thing with this patch, so I'm going to put it back and a? again for aurora / beta.

The whole non-indexing of messages thing I was experiencing is (I believe) a separate bug. I'll file that in a second.

Comment 15

[Mike Conley (:mconley) (:⚙️)]

Re-landed on comm-central as https://hg.mozilla.org/comm-central/rev/13ea978c6c41

Comment 16

[Mike Conley (:mconley) (:⚙️)]

comm-aurora: https://hg.mozilla.org/releases/comm-aurora/rev/516931b95293
comm-beta: https://hg.mozilla.org/releases/comm-beta/rev/0df4bccfc5f3