776566 - Deferred Gloda indexing for IM conversations

Status: RESOLVED FIXED

(Thunderbird :: Instant Messaging, defect)

Description

[Florian Quèze [:florian]]

This happens when the first message of a conversation is received, because there's a race between the gloda indexing that now happens on the fly, and the logger that writes the new message to disk, and the indexing code is unhappy that the log file for the conversation doesn't exist yet, causing this JS error:
[Exception... "'[JavaScript Error: "logFile is null" {file: "resource:///modules/index_im.js" line: 278}]' when calling method: [nsIObserver::observe]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: file:///.../DailyDebug.app/Contents/MacOS/components/imConversations.js :: <TOP_LEVEL> :: line 237"  data: yes]

Comment 1

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

(In reply to Florian Quèze from comment #0)
> This happens when the first message of a conversation is received, because
> there's a race between the gloda indexing that now happens on the fly, and
> the logger that writes the new message to disk, and the indexing code is
> unhappy that the log file for the conversation doesn't exist yet, causing
> this JS error:
> [Exception... "'[JavaScript Error: "logFile is null" {file:
> "resource:///modules/index_im.js" line: 278}]' when calling method:
> [nsIObserver::observe]"  nsresult: "0x80570021
> (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame ::
> file:///.../DailyDebug.app/Contents/MacOS/components/imConversations.js ::
> <TOP_LEVEL> :: line 237"  data: yes]

Florian:

Is the best solution to simply kick out of the indexer observer function if the logFile is null?

-Mike

Comment 2

[Florian Quèze [:florian]]

Do you mean add a null check for logFile and return early if it's null?

Given how annoyed I am by seeing this JS error all the time, I would r+ a patch doing that but it's really just silencing out the error, not fixing the bug.

If we do that, IM conversations with only one message won't be indexed until a restart.

I don't have a good and easy solution to offer (otherwise I would have already attached a patch ;)).

Comment 3

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

Attachment: Patch v1

Ok, my solution is to cause ConversationLog to call its own _init function on construction. This way, the logFile is available to the first caller immediately, instead of when the first message has been written to it.

I believe this eliminates the race. I gave this a spin, and I couldn't reproduce the error message.

Comment 4

[Florian Quèze [:florian]]

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

This looks like a more elegant way to hide the real issue, I don't think it fixes the race.

The real solution may be to fix the performance issue discussed in bug 740499 comment 2 and bug 740499 comment 3, ie. find a way to not have to index conversations immediately when a new message arrives.

Comment 5

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

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

Withdrawing review request, since we're just wallpapering over the problem.

So, summarizing the discussion that Florian and I had yesterday, we've come up with two approaches to a solution:

1) Introduce a new observation topic for when a message has been written to the log, and have Gloda observe *that* instead of when a new conversation has been started.

2) Find a way of delaying the indexing of IM messages until some time in the future - this could also eliminate some performance issues (see https://bugzilla.mozilla.org/show_bug.cgi?id=776566#c4).

Comment 6

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

Ok, summarising a discussion I just had on IRC with Florian and Patrick Cloke:

We observe the "new-text" notification, and if the unread-message-count-changed is set to 0, we start a timer for a deferred indexing job on the conversation.  Subsequent "new-text" notifications are ignored until the indexing job is done.

We also observe when the conversation is closed, and index immediately (or deferred, whichever is easiest).

Florian - does that sound right?

Comment 7

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

Ok, some further clarity:

We observe the "new-text" notification, and check to see if the unread-messages count on the associated conversation is set to 0.  If so, we know that the user is viewing this conversation right now, and we schedule a deferred indexing job on this conversation with a timer.

We also observe when the unread-message count is set to 0 - this is when the user has selected a conversation that's been active in the background. Once this happens, we schedule a deferred indexing job on that conversation with a timer.

Finally, we observe when a conversation is closed, and index immediately (or deferred, whichever is easiest).

Until I hear otherwise, I'm going to assume this is how we want to move forward with this.

Comment 8

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

Hm, it seems that "unread-message-count-changed" doesn't get fired anytime, from anywhere.

This is strange, because we seem to have some code that observes unread-message-count-changed... (http://mxr.mozilla.org/comm-central/search?string=unread-message-count-changed)

The notification that *is* sent is unread-im-count-changed, but this seems to be application global, as opposed to conversation specific.

Comment 9

[Florian Quèze [:florian]]

(In reply to Mike Conley (:mconley) from comment #8)
> Hm, it seems that "unread-message-count-changed" doesn't get fired anytime,
> from anywhere.
> 
> This is strange, because we seem to have some code that observes
> unread-message-count-changed...
> (http://mxr.mozilla.org/comm-central/search?string=unread-message-count-
> changed)

This fires the notification:
/chat/components/src/imConversations.js
    line 126 -- observer.observe(this, "unread-message-count-changed",

Comment 10

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

(In reply to Florian Quèze from comment #9)
> (In reply to Mike Conley (:mconley) from comment #8)
> > Hm, it seems that "unread-message-count-changed" doesn't get fired anytime,
> > from anywhere.
> > 
> > This is strange, because we seem to have some code that observes
> > unread-message-count-changed...
> > (http://mxr.mozilla.org/comm-central/search?string=unread-message-count-
> > changed)
> 
> This fires the notification:
> /chat/components/src/imConversations.js
>     line 126 -- observer.observe(this, "unread-message-count-changed",

Ah, cool - I was looking for notifyObservers. Alright, thanks!

Comment 11

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

Attachment: Deferred indexing WIP patch 1

How does this look? Are there any edge cases I'm not catching?

Comment 12

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

(In reply to Mike Conley (:mconley) from comment #11)
> Created attachment 646674 [details] [diff] [review]
> Deferred indexing WIP patch 1
> 
> How does this look? Are there any edge cases I'm not catching?

(Please ignore the dump in imConversations.js - forgot to scrub a sanity check)

Comment 13

[Florian Quèze [:florian]]

Comment on attachment 646674 [details] [diff] [review]
Deferred indexing WIP patch 1

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

I like the direction where this is going. I'm a bit sad that you had to make this file deal with both UI conversations (imIConversation) and prpl conversations (prplIConversation), but I'm glad to see you didn't confuse them and haven't messed up their ids :).

::: mail/components/im/modules/index_im.js
@@ +270,5 @@
> +    let convId = aConversation.id;
> +
> +    // If we've already scheduled this conversation to be indexed, let's
> +    // not repeat.
> +    if (convId in this._scheduledIndexingJobs)

Isn't this somehow duplicating the already existing this._knownConversations[convId].indexPending value and test?

Maybe you can replace that boolean and store the value returned by setTimeout in this._knownConversations[convId].indexPending?

@@ +310,5 @@
>      let job = new IndexingJob("indexIMConversation", null);
>      job.conversation = this._knownConversations[convId];
>      GlodaIndexer.indexJob(job);
> +
> +    // Now the clear job, so we can index in the future.

This comment doesn't seem very clear to me, I think rephrasing it could help.

@@ +332,5 @@
> +    if (aTopic == "unread-message-count-changed") {
> +      // We get this notification by attaching observers to conversations
> +      // directly (see the new-conversation handler for when we attach).
> +      if (aSubject.unreadIncomingMessageCount == 0) {
> +        // Ok, we just read a bunch of unread messages. We can index now.

This comment doesn't really help me in remembering why we had to add this case in addition to listening for the "new-text" notification.

I think I would like the comment to say explicitly that this is for when a conversation that has received messages in the background has been displayed.

@@ +340,5 @@
> +    }
> +
> +    if (aTopic == "conversation-closed") {
> +      // Start an indexing job on this conversation immediately.
> +      this._beginIndexingJob(aSubject);

If a user selects a conversation before closing it (likely), isn't there a timer that needs to be canceled if you start the indexing job immediately?

I'm wondering if we can somehow detect here if the conversation has received new messages since the last index, so that we can avoid reindexing an identical conversation.

@@ +352,5 @@
> +      let conv = aSubject.conversation;
> +      if (!conv) {
> +        // No conversation associated with this message - something has
> +        // gone horribly wrong. Bail out.
> +        return;

Do you have a reason to expect this will happen? If so, should this throw an exception instead of returning silently?

@@ +359,5 @@
> +      let uiConv = Services.conversations.getUIConversation(conv);
> +      if (!uiConv) {
> +        // No UIConversation associated with the conversation... something
> +        // has gone horribly wrong.
> +        return;

Same question here :).

Comment 14

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

(In reply to Florian Quèze from comment #13)
> Comment on attachment 646674 [details] [diff] [review]
> Deferred indexing WIP patch 1
> 
> Review of attachment 646674 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I like the direction where this is going. I'm a bit sad that you had to make
> this file deal with both UI conversations (imIConversation) and prpl
> conversations (prplIConversation), 

Is there a way I can avoid that?

> ::: mail/components/im/modules/index_im.js
> @@ +270,5 @@
> > +    let convId = aConversation.id;
> > +
> > +    // If we've already scheduled this conversation to be indexed, let's
> > +    // not repeat.
> > +    if (convId in this._scheduledIndexingJobs)
> 
> Isn't this somehow duplicating the already existing
> this._knownConversations[convId].indexPending value and test?

It looks like the meaning of knownConversations is that "I've been asked to index this conversation at least once, and I know about logFile and convObj, so I've cached them.".  At the time of scheduling an indexing job, knowing about logFile and convObj might not be possible (hence the error in the console that this bug is filed about), and so the cache can't be created.

> Maybe you can replace that boolean and store the value returned by
> setTimeout in this._knownConversations[convId].indexPending?

Would you be alright if I removed the indexPending boolean instead? 

> 
> @@ +310,5 @@
> >      let job = new IndexingJob("indexIMConversation", null);
> >      job.conversation = this._knownConversations[convId];
> >      GlodaIndexer.indexJob(job);
> > +
> > +    // Now the clear job, so we can index in the future.
> 
> This comment doesn't seem very clear to me, I think rephrasing it could help.

Good call. I must have gone temporarily dyslexic. :)

> 
> @@ +332,5 @@
> > +    if (aTopic == "unread-message-count-changed") {
> > +      // We get this notification by attaching observers to conversations
> > +      // directly (see the new-conversation handler for when we attach).
> > +      if (aSubject.unreadIncomingMessageCount == 0) {
> > +        // Ok, we just read a bunch of unread messages. We can index now.
> 
> This comment doesn't really help me in remembering why we had to add this
> case in addition to listening for the "new-text" notification.
> 
> I think I would like the comment to say explicitly that this is for when a
> conversation that has received messages in the background has been displayed.

Ok, deal.

> 
> @@ +340,5 @@
> > +    }
> > +
> > +    if (aTopic == "conversation-closed") {
> > +      // Start an indexing job on this conversation immediately.
> > +      this._beginIndexingJob(aSubject);
> 
> If a user selects a conversation before closing it (likely), isn't there a
> timer that needs to be canceled if you start the indexing job immediately?
> 
> I'm wondering if we can somehow detect here if the conversation has received
> new messages since the last index, so that we can avoid reindexing an
> identical conversation.

I guess we can tell if a conversation hasn't changed by checking to see if an indexing job has been scheduled. If it hasn't, the conversation hasn't changed since the last index, and we're good to just close. Does this sound right?

> 
> Do you have a reason to expect this will happen? If so, should this throw an
> exception instead of returning silently?
> 
> @@ +359,5 @@
> > +      let uiConv = Services.conversations.getUIConversation(conv);
> > +      if (!uiConv) {
> > +        // No UIConversation associated with the conversation... something
> > +        // has gone horribly wrong.
> > +        return;
> 
> Same question here :).

This is me being defensive. I can remove those if you'd like, or throw. It's up to you.

Comment 15

[Florian Quèze [:florian]]

(In reply to Mike Conley (:mconley) from comment #14)
> (In reply to Florian Quèze from comment #13)
> > Comment on attachment 646674 [details] [diff] [review]

> I'm a bit sad that you had to make
> > this file deal with both UI conversations (imIConversation) and prpl
> > conversations (prplIConversation), 
> 
> Is there a way I can avoid that?

I don't see any.

> > Isn't this somehow duplicating the already existing
> > this._knownConversations[convId].indexPending value and test?
> 
> It looks like the meaning of knownConversations is that "I've been asked to
> index this conversation at least once, and I know about logFile and convObj,
> so I've cached them.".  At the time of scheduling an indexing job, knowing
> about logFile and convObj might not be possible (hence the error in the
> console that this bug is filed about), and so the cache can't be created.

The cache can be created with logFile: null, and the log file would be cached only the first time we actually index the conversation. I don't see why convObj wouldn't be possible to access at the time of scheduling.

> > Maybe you can replace that boolean and store the value returned by
> > setTimeout in this._knownConversations[convId].indexPending?
> 
> Would you be alright if I removed the indexPending boolean instead?

This may not be the best solution, but yes, it would be alright.

> > @@ +340,5 @@
> > > +    }
> > > +
> > > +    if (aTopic == "conversation-closed") {
> > > +      // Start an indexing job on this conversation immediately.
> > > +      this._beginIndexingJob(aSubject);
> > 
> > If a user selects a conversation before closing it (likely), isn't there a
> > timer that needs to be canceled if you start the indexing job immediately?
> > 
> > I'm wondering if we can somehow detect here if the conversation has received
> > new messages since the last index, so that we can avoid reindexing an
> > identical conversation.
> 
> I guess we can tell if a conversation hasn't changed by checking to see if
> an indexing job has been scheduled. If it hasn't, the conversation hasn't
> changed since the last index, and we're good to just close. Does this sound
> right?

No :(. If a conversation with unread messages is closed without being displayed first, the unread messages have never been indexed.

Maybe we could count the unindexed messages? (this._knownConversations[convId].pendingMessages, initialized at 0, incremented each time we receive the new-text notification for a message that will be logged, and reset whenever the conversation is actually indexed)

This would let us know for sure whether the conversation that is being closed needs to be reindexed or not.

I'm not sure if this is a useful optimization or just overkill.

> > Do you have a reason to expect this will happen? If so, should this throw an
> > exception instead of returning silently?
> > 
> > @@ +359,5 @@
> > > +      let uiConv = Services.conversations.getUIConversation(conv);
> > > +      if (!uiConv) {
> > > +        // No UIConversation associated with the conversation... something
> > > +        // has gone horribly wrong.
> > > +        return;
> > 
> > Same question here :).
> 
> This is me being defensive.

Silently eating JS errors isn't really what I call being defensive ;).

> I can remove those if you'd like, or throw. It's
> up to you.

Either is fine with me, but if I was editing the patch I would just remove, as the shorter the code is, the less time it takes to go through it the next time we need to check something in it :).

Comment 16

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

(In reply to Florian Quèze from comment #15)
> (In reply to Mike Conley (:mconley) from comment #14)
> I'm not sure if this is a useful optimization or just overkill.
> 

Bah, let's punt. Let's not make this more complicated than it needs to be right now.

> > > Same question here :).
> > 
> > This is me being defensive.
> 
> Silently eating JS errors isn't really what I call being defensive ;).
> 

Ha! :) Touché! I guess I was being defensive in my *considering* those cases...but yeah, my reaction is poor.  Good call.

> Either is fine with me, but if I was editing the patch I would just remove,
> as the shorter the code is, the less time it takes to go through it the next
> time we need to check something in it :).

Ok, fair enough.

Comment 17

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

Attachment: Patch v2

Comment 18

[Florian Quèze [:florian]]

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

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

r=me with the details I mentioned addressed.
Note: I haven't tested this patch, I'm assuming you did :).

::: mail/components/im/modules/index_im.js
@@ +285,5 @@
> +    if (this._knownConversations[convId].scheduledIndex == null) {
> +      // Ok, let's schedule the job.
> +      this._knownConversations[convId].scheduledIndex = setTimeout(function() {
> +        this._beginIndexingJob(aConversation);
> +      }.bind(this), kIndexingDelay);

Why not this._beginIndexingJob.bind(this, aConversation) instead of function() { this._beginIndexingJob(aConversation); }.bind(this) ?

@@ +328,5 @@
> +    this._knownConversations[convId].scheduledIndex = null;
> +  },
> +
> +  observe: function logger_observe(aSubject, aTopic, aData) {
> +

nit: I don't think we usually start functions with an empty line.

@@ +343,5 @@
> +    }
> +
> +    if (aTopic == "unread-message-count-changed") {
> +      // We get this notification by attaching observers to conversations
> +      // directly (see the new-conversation handler for when we attach).

You meant new-ui-conversation.

@@ +350,5 @@
> +        // that had been in the background and receiving messages was suddenly
> +        // moved to the foreground and displayed to the user. We schedule an
> +        // indexing job on this conversation now, since we want to index messages
> +        // that the user has seen.
> +        this._scheduleIndexingJob(aSubject.target);

When the conversation is already selected and an incoming message arrives, it's possible unread-message-count-changed is fired twice in a row, first with 1 and then with 0 as the unread count (once the UI marks the message as read).
So it's possible (and even likely) that for incoming messages we call _scheduleIndexingJob twice. I don't think that matters, it will just do nothing the second time.

@@ +359,5 @@
> +    if (aTopic == "conversation-closed") {
> +      // If there's a scheduled indexing job, cancel it, because we're going
> +      // to index now.
> +      if (aSubject.id in this._knownConversations
> +          && this._knownConversations[aSubject.id].scheduledIndex != null) {

In code I write, I usually put the && and || operators at the end of the previous line rather than at the beginning of the next one. I'm not sure if there's a consistent policy for Thunderbird for this or not.

@@ +364,5 @@
> +        clearTimeout(this._knownConversations[aSubject.id].scheduledIndex);
> +      }
> +
> +      this._beginIndexingJob(aSubject);
> +      delete this._knownConversations[aSubject.id];

aSubject.id is used 4 times in the conversation-closed handling. Maybe use a let convId = aSubject.id; variable?

Comment 19

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

(In reply to Florian Quèze from comment #18)
> Comment on attachment 647556 [details] [diff] [review]
> Patch v2
> 
> Review of attachment 647556 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Note: I haven't tested this patch, I'm assuming you did :).

I did indeed.

> 
> ::: mail/components/im/modules/index_im.js
> @@ +285,5 @@
> > +    if (this._knownConversations[convId].scheduledIndex == null) {
> > +      // Ok, let's schedule the job.
> > +      this._knownConversations[convId].scheduledIndex = setTimeout(function() {
> > +        this._beginIndexingJob(aConversation);
> > +      }.bind(this), kIndexingDelay);
> 
> Why not this._beginIndexingJob.bind(this, aConversation) instead of
> function() { this._beginIndexingJob(aConversation); }.bind(this) ?
> 

Sure, done.

> @@ +328,5 @@
> > +    this._knownConversations[convId].scheduledIndex = null;
> > +  },
> > +
> > +  observe: function logger_observe(aSubject, aTopic, aData) {
> > +
> 
> nit: I don't think we usually start functions with an empty line.

Fixed.

> 
> @@ +343,5 @@
> > +    }
> > +
> > +    if (aTopic == "unread-message-count-changed") {
> > +      // We get this notification by attaching observers to conversations
> > +      // directly (see the new-conversation handler for when we attach).
> 
> You meant new-ui-conversation.
> 

Good catch! Fixed.

> @@ +350,5 @@
> > +        // that had been in the background and receiving messages was suddenly
> > +        // moved to the foreground and displayed to the user. We schedule an
> > +        // indexing job on this conversation now, since we want to index messages
> > +        // that the user has seen.
> > +        this._scheduleIndexingJob(aSubject.target);
> 
> When the conversation is already selected and an incoming message arrives,
> it's possible unread-message-count-changed is fired twice in a row, first
> with 1 and then with 0 as the unread count (once the UI marks the message as
> read).
> So it's possible (and even likely) that for incoming messages we call
> _scheduleIndexingJob twice. I don't think that matters, it will just do
> nothing the second time.
> 

True. Our solution isn't perfect here, but I think it'll do.

> @@ +359,5 @@
> > +    if (aTopic == "conversation-closed") {
> > +      // If there's a scheduled indexing job, cancel it, because we're going
> > +      // to index now.
> > +      if (aSubject.id in this._knownConversations
> > +          && this._knownConversations[aSubject.id].scheduledIndex != null) {
> 
> In code I write, I usually put the && and || operators at the end of the
> previous line rather than at the beginning of the next one. I'm not sure if
> there's a consistent policy for Thunderbird for this or not.
> 

According to the Mozilla JS style guide - you're right - I should put the && at the end of the previous line. Fixed.

> @@ +364,5 @@
> > +        clearTimeout(this._knownConversations[aSubject.id].scheduledIndex);
> > +      }
> > +
> > +      this._beginIndexingJob(aSubject);
> > +      delete this._knownConversations[aSubject.id];
> 
> aSubject.id is used 4 times in the conversation-closed handling. Maybe use a
> let convId = aSubject.id; variable?

Good idea. Done.

> r=me with the details I mentioned addressed.

Thanks!

Comment 20

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

Attachment: Patch v3 [r+'d by florian]

Comment 21

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

Updating bug summary to describe the bigger picture, beyond fixing the "logFile is null" {file: "resource:///modules/index_im.js" JS error.

Comment 22

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

comm-central: https://hg.mozilla.org/comm-central/rev/112daf200c72

Comment 23

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

comm-aurora: https://hg.mozilla.org/releases/comm-aurora/rev/439a8cb83577
comm-beta: https://hg.mozilla.org/releases/comm-beta/rev/bf0a4d89f903