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

RESOLVED FIXED in Thunderbird 17.0

Status

Thunderbird
Instant Messaging
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: mconley, Assigned: mconley)

Tracking

15 Branch
Thunderbird 17.0
x86
Windows 7

Thunderbird Tracking Flags

(thunderbird15 fixed, thunderbird16 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

5 years ago
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.
(Assignee)

Comment 1

5 years ago
I'm experiencing this in the latest beta, and on a trunk build.
(Assignee)

Updated

5 years ago
tracking-thunderbird15: --- → ?
tracking-thunderbird16: --- → ?
(Assignee)

Comment 2

5 years ago
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.
(Assignee)

Comment 3

5 years ago
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.
(Assignee)

Comment 4

5 years ago
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.
OS: All → Windows 7
(Assignee)

Comment 5

5 years ago
Created attachment 652206 [details] [diff] [review]
Patch v1

This fixes things on Windows for me.
Attachment #652206 - Flags: review?(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.  ;)
Attachment #652206 - Flags: review?(bwinton) → review-
(Assignee)

Comment 7

5 years ago
Created attachment 652208 [details] [diff] [review]
Patch v2

A for-reals patch now.
Attachment #652206 - Attachment is obsolete: true
Attachment #652208 - Flags: review?(bugmail)
(Assignee)

Comment 8

5 years ago
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 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)!
Attachment #652208 - Flags: review?(bugmail) → review+
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.
(Assignee)

Updated

5 years ago
Attachment #652208 - Flags: approval-comm-beta?
Attachment #652208 - Flags: approval-comm-aurora?
(Assignee)

Comment 11

5 years ago
comm-central: https://hg.mozilla.org/comm-central/rev/9a13835a35c7
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 17.0
(Assignee)

Comment 12

5 years ago
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...
Attachment #652208 - Flags: approval-comm-beta?
Attachment #652208 - Flags: approval-comm-aurora?
(Assignee)

Comment 13

5 years ago
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
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(Assignee)

Comment 14

5 years ago
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.
(Assignee)

Comment 15

5 years ago
Re-landed on comm-central as https://hg.mozilla.org/comm-central/rev/13ea978c6c41
Status: REOPENED → RESOLVED
Last Resolved: 5 years ago5 years ago
Resolution: --- → FIXED
(Assignee)

Updated

5 years ago
Attachment #652208 - Flags: approval-comm-beta?
Attachment #652208 - Flags: approval-comm-aurora?
Attachment #652208 - Flags: approval-comm-beta?
Attachment #652208 - Flags: approval-comm-beta+
Attachment #652208 - Flags: approval-comm-aurora?
Attachment #652208 - Flags: approval-comm-aurora+
(Assignee)

Comment 16

5 years ago
comm-aurora: https://hg.mozilla.org/releases/comm-aurora/rev/516931b95293
comm-beta: https://hg.mozilla.org/releases/comm-beta/rev/0df4bccfc5f3
status-thunderbird15: --- → fixed
status-thunderbird16: --- → fixed
tracking-thunderbird15: ? → ---
tracking-thunderbird16: ? → ---
You need to log in before you can comment on or make changes to this bug.