Last Comment Bug 783022 - After the initial message, conversations are not indexed or searchable until TB is restarted
: After the initial message, conversations are not indexed or searchable until ...
Product: Thunderbird
Classification: Client Software
Component: Instant Messaging (show other bugs)
: 15 Branch
: x86 Windows 7
-- normal (vote)
: Thunderbird 17.0
Assigned To: Mike Conley (:mconley)
Depends on:
  Show dependency treegraph
Reported: 2012-08-15 10:47 PDT by Mike Conley (:mconley)
Modified: 2012-08-20 07:17 PDT (History)
5 users (show)
See Also:
Crash Signature:
QA Whiteboard:
Iteration: ---
Points: ---

Patch v1 (19 bytes, patch)
2012-08-15 13:39 PDT, Mike Conley (:mconley)
bwinton: review-
Details | Diff | Splinter Review
Patch v2 (1.23 KB, patch)
2012-08-15 13:47 PDT, Mike Conley (:mconley)
bugmail: review+
standard8: approval‑comm‑aurora+
standard8: approval‑comm‑beta+
Details | Diff | Splinter Review

Description User image Mike Conley (:mconley) 2012-08-15 10:47:40 PDT

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 User image Mike Conley (:mconley) 2012-08-15 10:48:41 PDT
I'm experiencing this in the latest beta, and on a trunk build.
Comment 2 User image Mike Conley (:mconley) 2012-08-15 11:03:14 PDT
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 User image Mike Conley (:mconley) 2012-08-15 12:26:58 PDT
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 User image Mike Conley (:mconley) 2012-08-15 13:33:00 PDT
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 User image Mike Conley (:mconley) 2012-08-15 13:39:29 PDT
Created attachment 652206 [details] [diff] [review]
Patch v1

This fixes things on Windows for me.
Comment 6 User image Blake Winton (:bwinton) (:☕️) 2012-08-15 13:41:40 PDT
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.


Blake.  ;)
Comment 7 User image Mike Conley (:mconley) 2012-08-15 13:47:25 PDT
Created attachment 652208 [details] [diff] [review]
Patch v2

A for-reals patch now.
Comment 8 User image Mike Conley (:mconley) 2012-08-15 14:20:48 PDT
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 User image Andrew Sutherland [:asuth] 2012-08-15 16:10:58 PDT
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 User image Mark Banner (:standard8) 2012-08-16 01:49:47 PDT
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 User image Mike Conley (:mconley) 2012-08-16 07:17:06 PDT
Comment 12 User image Mike Conley (:mconley) 2012-08-17 07:06:18 PDT
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 User image Mike Conley (:mconley) 2012-08-17 07:09:47 PDT
Backed out patch on comm-central for now until I can figure out what's going on:
Comment 14 User image Mike Conley (:mconley) 2012-08-17 11:00:02 PDT
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 User image Mike Conley (:mconley) 2012-08-17 11:08:27 PDT
Re-landed on comm-central as

Note You need to log in before you can comment on or make changes to this bug.