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 ...
Status: RESOLVED FIXED
:
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) - (needinfo me!)
:
Mentors:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-08-15 10:47 PDT by Mike Conley (:mconley) - (needinfo me!)
Modified: 2012-08-20 07:17 PDT (History)
5 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
fixed
fixed


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

Description Mike Conley (:mconley) - (needinfo me!) 2012-08-15 10:47:40 PDT
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) - (needinfo me!) 2012-08-15 10:48:41 PDT
I'm experiencing this in the latest beta, and on a trunk build.
Comment 2 Mike Conley (:mconley) - (needinfo me!) 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 Mike Conley (:mconley) - (needinfo me!) 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 Mike Conley (:mconley) - (needinfo me!) 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 Mike Conley (:mconley) - (needinfo me!) 2012-08-15 13:39:29 PDT
Created attachment 652206 [details] [diff] [review]
Patch v1

This fixes things on Windows for me.
Comment 6 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.

r-.

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

A for-reals patch now.
Comment 8 Mike Conley (:mconley) - (needinfo me!) 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 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 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 Mike Conley (:mconley) - (needinfo me!) 2012-08-16 07:17:06 PDT
comm-central: https://hg.mozilla.org/comm-central/rev/9a13835a35c7
Comment 12 Mike Conley (:mconley) - (needinfo me!) 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 Mike Conley (:mconley) - (needinfo me!) 2012-08-17 07:09:47 PDT
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) - (needinfo me!) 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 Mike Conley (:mconley) - (needinfo me!) 2012-08-17 11:08:27 PDT
Re-landed on comm-central as https://hg.mozilla.org/comm-central/rev/13ea978c6c41
Comment 16 Mike Conley (:mconley) - (needinfo me!) 2012-08-20 07:17:41 PDT
comm-aurora: https://hg.mozilla.org/releases/comm-aurora/rev/516931b95293
comm-beta: https://hg.mozilla.org/releases/comm-beta/rev/0df4bccfc5f3

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