1416469 - "gMsgCompose is null" in spellchecker observer in mozmill/composition tests of Thunderbird

Status: RESOLVED FIXED

(Thunderbird :: Message Compose Window, defect)

Description

[:aceman]

There is some silent bustage in Thunderbird's compose window code.

See e.g. log at https://archive.mozilla.org/pub/thunderbird/tinderbox-builds/comm-central-linux/1510353971/comm-central_ubuntu32_vm_test-mozmill-bm04-tests1-linux32-build390.txt.gz
Most tests in mozmill/composition/ spew this error:
JavaScript error: chrome://messenger/content/messengercompose/MsgComposeCommands.js, line 3622: TypeError: gMsgCompose is null (always the same line)

Some produce:
JavaScript error: chrome://messenger/content/messengercompose/MsgComposeCommands.js, line 3625: NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIInlineSpellChecker.ignoreWords]

composition/test-charset-edit.js | test_wrong_reply_charset produces:
16:33:08     INFO -  Running draft identity test0
JavaScript error: resource:///modules/jsmime.jsm, line 39: : Component returned failure code: 0x80500001 [nsIScriptableUnicodeConverter.charset]

Comment 1

[:aceman]

The gMsgCompose is suddenly vanished on linux, but can still be seen on Windows.
I think I know what is going on, so the vanishing is OK as it is a timing issue.
The line has changed after the latest checkin that touched MsgComposeCommands:
JavaScript error: chrome://messenger/content/messengercompose/MsgComposeCommands.js, line 3778: TypeError: gMsgCompose is null

Comment 2

[:aceman]

Attachment: 1416469-charset.patch

nsIScriptableUnicodeConverter.charset was throwing on an unsupported charset we use in a test. Fall back to ASCII in that case as discussed on IRC.

Try run: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=7f57710abf021176607ceb5e8d8ec56ed79dd466

Comment 3

[Jorg K (CEST = GMT+2)]

(In reply to :aceman from comment #2)
> nsIScriptableUnicodeConverter.charset was throwing on an unsupported charset ...
Why is US-ASCII good to encode anything? If you use that, you might as well use its canonical name "windows-1252". But why not UTF-8?

Comment 4

[:aceman]

Attachment: 1416469-speller.patch

I think the tests are very fast and close the compose window before the spelling checker gets initialized. But we have an observer to wait for the initialization. When the observer fires, we should not touch gMsgCompose.editor and call speller methods when the objects are longer valid.

Try runs,
Linux: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=7f57710abf021176607ceb5e8d8ec56ed79dd466

Windows: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=ce6cbbbeb0db32cd990452d4464c11cd00283ea9

Comment 5

[:aceman]

(In reply to Jorg K [exited Thunderbird project due to non-renewal of contract] from comment #3)
> (In reply to :aceman from comment #2)
> > nsIScriptableUnicodeConverter.charset was throwing on an unsupported charset ...
> Why is US-ASCII good to encode anything? If you use that, you might as well
> use its canonical name "windows-1252". But why not UTF-8?

Setting US-ASCII seems to make it return back windows-1252 anyway. But don't make me write windows-1252, I don't know how anything coming from Windows could become anything "canonical" :) Yes, UTF-8 may be a better default, but jcranmer said ASCII. Maybe there is a spec for it.

Comment 6

[Jorg K (CEST = GMT+2)]

Comment on attachment 8927601 [details] [diff] [review]
1416469-speller.patch

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

::: mail/components/compose/content/MsgComposeCommands.js
@@ +3778,5 @@
> +        // At the time the speller finally got initialized, we may already be closing
> +        // the compose together with the speller, so we need to check if they
> +        // are still valid.
> +        // XXX may this leave the observer registered globally forever if we lose
> +        // gMsgCompose before the observer for this particular editor is removed?

Yes. Registration for observers is global. The scheme used here seems to be highly prone to failure. It's also ugly that you don't have an observer object. Defining an 'observe' function and passing it into remove may look elegant, but gives no handle to removing the observer elsewhere. And as we see, we might already not have the correct information when it triggers.

I would use the same technique implemented as for dictionaryRemovalObserver. Every window has one and it's removed reliably. You can do the same thing here, you can also remove it here in the callback, but also in ComposeUnload(). Its member variable keeps track of the removal state. f-
Original code from here:
https://hg.mozilla.org/comm-central/rev/55edd6e9957e#l1.14

Comment 7

[Jorg K (CEST = GMT+2)]

(In reply to :aceman from comment #5)
> Setting US-ASCII seems to make it return back windows-1252 anyway. But don't
> make me write windows-1252, I don't know how anything coming from Windows
> could become anything "canonical" :)
windows-1252 is the canonical name for US-ASCII, ISO-8859-1 and friends:
https://searchfox.org/mozilla-central/rev/7fb4cc447c06f14fe3b5c6b0c9d103a860937250/dom/encoding/labelsencodings.properties#134
Also see bug 1363281 comment #43.
IMHO, you should use "windows-1252" or UTF-8.

Comment 8

[:aceman]

(In reply to Jorg K [exited Thunderbird project due to non-renewal of contract] from comment #6)
> Yes. Registration for observers is global. The scheme used here seems to be
> highly prone to failure. It's also ugly that you don't have an observer
> object. Defining an 'observe' function and passing it into remove may look
> elegant, but gives no handle to removing the observer elsewhere. And as we
> see, we might already not have the correct information when it triggers.

Yes, there is no handle to remove the observer or at least some identifier inside the observer to decide if to remove this particular one. The unique gMsgCompose.editor object is not accessible when unloading composer. I'd like to avoid this leak if possible, even though it was there before.
 
> I would use the same technique implemented as for dictionaryRemovalObserver.
> Every window has one and it's removed reliably. You can do the same thing
> here, you can also remove it here in the callback, but also in
> ComposeUnload(). Its member variable keeps track of the removal state.

Good idea, thanks!

Comment 9

[:aceman]

We may need multiple objects to track the observers as a single compose window may need to stack multiple ignoreWords until the speller is up. Or I can just stack the words inside the object in some array that will be read once the observer fires.

Comment 10

[Jorg K (CEST = GMT+2)]

Looking at the original change
https://hg.mozilla.org/comm-central/rev/55edd6e9957e#l1.14
and also at MsgComposeCommands.js, the gSpellChecker is associated with the editor of the message body, not the one of the message subject. The latter is retrieved separately with
        let inlineSpellChecker =
          GetMsgSubjectElement().editor.getInlineSpellChecker(false);
when needed.

The original patch tries to wait for the body spell check to complete and then add (potentially multiple) words from the recipients. I don't understand comment #8. Even if we enter addRecipientsToIgnoreList() multiple times, there is only one observer necessary to wait for the body spell check to complete. As I said in comment #6, of course without having tried it, there should be one observer associated with that window which administers its own removal, so you can call its remove function multiple times, the last time in ComposeUnload().

Comment 11

[:aceman]

(In reply to Jorg K [no longer working on Thunderbird due to non-renewal of contract] from comment #10)
> The original patch tries to wait for the body spell check to complete and
> then add (potentially multiple) words from the recipients. I don't
> understand comment #8. Even if we enter addRecipientsToIgnoreList() multiple
> times, there is only one observer necessary to wait for the body spell check

Comment 9? When we call addRecipientsToIgnoreList multiple times before the speller is initialized currently we set up multiple observers, each with different value of tokenizedNames sent to .ignoreWords. So I'll try to work with one observer only and accumulate the words into an array.

Comment 12

[Jorg K (CEST = GMT+2)]

Oops, you are right, if addRecipientsToIgnoreList() gets called multiple times while the spell check is still pending, you create multiple observers, although that's not a likely case since the function is called from LoadIdentity() and no user will switch identities so fast that this case will occur.

That said, the observer function
function observe(subject, topic, data) {
        if (subject == gMsgCompose.editor)
        {
          Services.obs.removeObserver(observe, topic);
          gSpellChecker.mInlineSpellChecker.ignoreWords(tokenizedNames, tokenizedNames.length);
        }
      }
accesses values from the defining environment, namely 'tokenizedNames', which is possible since the function is executed in the context it was defined in and therefore 'tokenizedNames' is carried into the function via "closure":
https://developer.mozilla.org/en-US/docs/Web/JavaScript/Closures

If you do one observer, you'd have to accumulate the tokens and stuff them all into the spell checker once "spell check end" fires. But you've already said that.

Looking at the patch again, do you need |if (gSpellChecker.enabled)|? How would it be pending and then get into the observer at some stage if it weren't enabled in the first place?

Comment 13

[:aceman]

(In reply to Jorg K [no longer working on Thunderbird due to non-renewal of contract] from comment #12)
> Oops, you are right, if addRecipientsToIgnoreList() gets called multiple
> times while the spell check is still pending, you create multiple observers,
> although that's not a likely case since the function is called from
> LoadIdentity() and no user will switch identities so fast that this case
> will occur.

But tests do. This whole bug (except the charset bug) is for tests which are too fast and tear down the composer (if they do not test the spellchecker specifically).
Of course no proper user would be so fast :)
 
> Looking at the patch again, do you need |if (gSpellChecker.enabled)|? How
> would it be pending and then get into the observer at some stage if it
> weren't enabled in the first place?

Yes, that is needed. That is for the error
JavaScript error: chrome://messenger/content/messengercompose/MsgComposeCommands.js, line 3625: NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIInlineSpellChecker.ignoreWords]

In that case, gMsgCompose still isn't null and passes the if(), but nsIInlineSpellChecker.ignoreWords already throws. I assume we are already halfway through ComposeUnload and speller is already disabled (and gSpellChecker.enabled is false), but gMsgCompose not.

Comment 14

[Jorg K (CEST = GMT+2)]

Hmm, NS_ERROR_NOT_INITIALIZED doesn't sound like the spell checker were disabled. I don't quite get how
  gSpellChecker.mInlineSpellChecker.spellCheckPending
can return 'true' and 
  gSpellChecker.mInlineSpellChecker.ignoreWords()
throws with "not initialised".

https://searchfox.org/mozilla-central/rev/7fb4cc447c06f14fe3b5c6b0c9d103a860937250/extensions/spellcheck/src/mozInlineSpellChecker.cpp#2051
https://searchfox.org/mozilla-central/rev/7fb4cc447c06f14fe3b5c6b0c9d103a860937250/extensions/spellcheck/src/mozInlineSpellChecker.cpp#1045

If it is like you said, that the whole thing is being shut down, then mNumPendingSpellChecks should have been set to zero and .spellCheckPending should not have returned 'true'. Anyway, that spell check integration into the editor is complicated code, maybe it has a quirk here we need to work around.

Comment 15

[:aceman]

(In reply to Jorg K [no longer working on Thunderbird due to non-renewal of contract] from comment #14)
> Hmm, NS_ERROR_NOT_INITIALIZED doesn't sound like the spell checker were
> disabled. I don't quite get how
>   gSpellChecker.mInlineSpellChecker.spellCheckPending
> can return 'true' and 
>   gSpellChecker.mInlineSpellChecker.ignoreWords()
> throws with "not initialised".

Those 2 calls run at completely different times, the latter one is inside the observer.

Comment 16

[Jorg K (CEST = GMT+2)]

Sure. spellCheckPending ran first and there was a pending spell check, so one would assume that inline spell checking was a) initialised, b) enabled and c) doing a check right now. Once done, it triggered the observer which in turn tried to add the words. I don't really understand how it can return "not initialised" since it was quite clearly initialised, unless, as you said, the inline spell checker was on the way out and "not initialised" really means "being shut down".

Anyway, I can see that testing .enabled avoid the problem, since that tests whether it's initialised:
https://searchfox.org/mozilla-central/rev/fe75164c55321e011d9d13b6d05c1e00d0a640be/toolkit/modules/InlineSpellChecker.jsm#113
and
https://searchfox.org/mozilla-central/rev/7fb4cc447c06f14fe3b5c6b0c9d103a860937250/extensions/spellcheck/src/mozInlineSpellChecker.cpp#749

Comment 17

[:aceman]

How would you like https://hg.mozilla.org/try-comm-central/rev/c645c041f16e98339d7a0c81f090a64cc1b91524 ?

I just wonder why in https://archive.mozilla.org/pub/thunderbird/try-builds/[e-mail]-8bc2c07da58ee5fc805bd882f7b8f01f68ecae4c/try-comm-central-linux64/try-comm-central_ubuntu64_vm_test-mozmill-bm54-tests1-linux64-build26.txt.gz in test composition/test-charset-edit.js | test_wrong_reply_charset it calls the observer so many times. It doesn't do it so much locally (look for the "ACE:observer" output).

Comment 18

[Jorg K (CEST = GMT+2)]

(In reply to :aceman from comment #17)
> How would you like ...
I like it. We also wanted to remove the observer in ComposeUnload().

I find the debug a little confusing, it would be better to see it with \n in the dump statements, and the "ACE:observer run" output only after testing the topic, not before. But hold on, there isn't a single "ACE:observer run" in the entire log(??).

Comment 19

[:aceman]

(In reply to Jorg K (GMT+1 - back on board soon) from comment #18)
> I like it. We also wanted to remove the observer in ComposeUnload().
We do, from enableInlineSpellCheck() which is called from ComposeUnload() with false.
 
> I find the debug a little confusing, it would be better to see it with \n in
> the dump statements, and the "ACE:observer run" output only after testing
> the topic, not before.

I'm not sure if we can get called with any other topic than what we registered with, but I copied this check from the dictionary observer object. We can leave that in if you like. OK, I added dump when we really run the observer code after topic check.

> But hold on, there isn't a single "ACE:observer run" in the entire log(??).

Right, I was too eager to prefix private methods (not to be called from outside) with "_" that I renamed the "observer" method so nothing was run when the observer fired :)

Better try: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=07b4cd171e6976d3ed8c3f42460dd56948a99160

Comment 20

[Jorg K (CEST = GMT+2)]

(In reply to :aceman from comment #19)
> > I like it. We also wanted to remove the observer in ComposeUnload().
> We do, from enableInlineSpellCheck() which is called from ComposeUnload()
> with false.
Hmm, why is it a good idea to put this call into enableInlineSpellCheck()? Isn't that unrelated? Why not remove the observer when calling with 'true'? Personally I'd stick the remove call directly into ComposeUnload(). What am I missing?

Comment 21

[:aceman]

It seems related to me, it is where gSpellChecker.enabled is set (that we use). Why remove the observer when we are enabling the checker? Yes, it would be strange if we turned speller off and then quickly on and only then the observer fires, but who knows ;) Do we want to loose the event when the speller is working again?

Comment 22

[Jorg K (CEST = GMT+2)]

I would clear all possible remnants when changing the speller state. If it was off before, there shouldn't be an observer handing around. These observers should really take care of themselves and whatever they miss is cleaned up at ComposeUnload() time with a comment:
// In some Mozmill tests, the window is closed so quickly that the observer 
// hasn't fired and removed itself yet, so let's remove it here.

Comment 23

[:aceman]

Attachment: 1416469-speller.patch

I have no problem with that, thanks.
I added removing the observer in enableInlineSpellCheck() only if the state is changing.
I also added clearing of the _ignoredWords array, that was missing yet.

Would you like to take the credit for looking at the patch so thoroughly by finishing the review? :)

Comment 24

[Jorg K (CEST = GMT+2)]

Comment on attachment 8927977 [details] [diff] [review]
1416469-speller.patch

Looks good, clear and elegant ;-)

I checked
https://archive.mozilla.org/pub/thunderbird/try-builds/[e-mail]-07b4cd171e6976d3ed8c3f42460dd56948a99160/try-comm-central-macosx64/try-comm-central_yosemite_r7_test-mozmill-bm106-tests1-macosx-build28.txt.gz
to confirm the following:

Does it work? Yes.
Do all the ugly JS errors go away? Yes.
(I ask myself where they came from all of a sudden since I did a survey of frequent JS errors in logs not so long ago and there weren't there.)
Is there any evidence that the observer ever runs and adds those words? Yes.

(In reply to :aceman from comment #23)
> Would you like to take the credit for looking at the patch so thoroughly by
> finishing the review? :)
I shouldn't.

Comment 25

[:aceman]

(In reply to Jorg K (GMT+1 - back on board soon) from comment #24)
> (I ask myself where they came from all of a sudden since I did a survey of
> frequent JS errors in logs not so long ago and there weren't there.)

I always think these timing induced errors come from changes in m-c (sometimes c-c). Something has changed in rendering/spellchecker/window handling/something new got async, so that suddenly the ComposeUnload gets run a tiny bit sooner than the spellchecker observer (while it was the other way round before).

> (In reply to :aceman from comment #23)
> > Would you like to take the credit for looking at the patch so thoroughly by
> > finishing the review? :)
> I shouldn't.

But I can understand the urge to do it :-P Thanks.

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/b78d73bcd985
do not call the inline spellchecker if compose window is already closing down. r=jorgk

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/c412f40f1eec
follow-up: fix comment. rs=comment-only

Comment 28

[Jorg K (CEST = GMT+2)]

Beta (TB 58):
https://hg.mozilla.org/releases/comm-beta/rev/be8285843861cdd63f770e7046e540865db8514f

Comment 29

[Jorg K (CEST = GMT+2)]

Comment on attachment 8927587 [details] [diff] [review]
1416469-charset.patch

This patch has bit rot and will rot even further when bug 1469499 lands.

Please move this to a new bug.