1645947 - C-C TB JavaScript error: resource:///modules/gloda/GlodaDatastore.jsm, line 1281: TypeError: can't access property "cancel", this._folderCleanupTimer is null

Status: NEW

(Thunderbird :: General, defect)

Description

[ISHIKAWA, Chiaki]

In my local xpcshell-tests since January (I have not checked older logs) I see the following error:

JavaScript error: resource:///modules/gloda/GlodaDatastore.jsm, line 1281: TypeError: can't access property "cancel", this._folderCleanupTimer is null

The code in question:
https://searchfox.org/comm-central/source/mailnews/db/gloda/modules/GlodaDatastore.jsm#1281

 // shutdown our folder cleanup timer, if active and null it out.
    if (this._folderCleanupActive) {
      this._folderCleanupTimer.cancel();
    }
    this._folderCleanupTimer = null;

The band-aid fix would be to add check for |this._folderCleanup| before calling cancel().
However, I suspect a possible screwup of keeping consistent state of |_folderCleanupActive| and |_folderCleanupTimer| .

The error is seen randomly when the following tests are executed.
That is, the error does not always happen at the given test. This suggests some async timing race(?)
15 comm/mail/components/extensions/test/xpcshell/test_ext_messages_query.js
1 comm/mail/components/extensions/test/xpcshell/test_ext_messages.js
1 xpcshell-jsaddrbook.ini:comm/mailnews/addrbook/test/unit/test_nsAbAutoCompleteSearch1.js
1 comm/mail/components/extensions/test/xpcshell/test_ext_experiments.js
1 comm/mail/components/extensions/test/xpcshell/test_ext_cloudFile.js

The number at the beginning of the line in the above list is the number of times the error appeared following the test.

I say "following the test" because the error does indeed seems to occur near the shutdown time.
The following is the excerpt from the latest log where the error occurs at the execution of most popular comm/mail/components/extensions/test/xpcshell/test_ext_messages_query.js:
Note the "WARNING: some msg dbs left open: '!m_dbCache.Length()'," message.
I wonder if this message is printed because of the failure of the proper shutdown of
glodadatabase due to the bug reported here.

 0:46.48 pid:1186774 {debug} SetSpec succeeded. : aSpec=mailbox://nobody@local%20folders/test1
 0:46.49 PASS  - Correct number of messages - Expected: 1, Actual: 1 - true == true
 0:46.49 PASS  - finished - true == true
 0:46.50 PASS  - test result correct - "finished" == "finished"
 0:46.50 pid:1186774 [1186774, Main Thread] WARNING: '!inner', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/ipc/JSWindowActorProtocol.cpp, line 172
 0:46.52 INFO (xpcshell/head.js) | test run_next_test 2 pending (2)
 0:46.53 INFO (xpcshell/head.js) | test finished (2)
 0:46.53 INFO (xpcshell/head.js) | test run_next_test 2 finished (1)
 0:46.53 INFO exiting test
 0:46.56 pid:1186774 JavaScript error: resource:///modules/gloda/GlodaDatastore.jsm, line 1281: TypeError: can't access property "cancel", this._folderCleanupTimer is null
 0:46.56 INFO "Cleaning up account [nsIMsgAccount: account1]"
 0:46.56 pid:1186774 {streamdebug} closing: mLogStream (= (nil) )->Close() 'Possible closing of LogStream.' in SetLogStream  at line 179 of /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsSpamSettings.cpp
 0:46.57 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "TypeError: can't access property "cancel", this._folderCleanupTimer is null" {file: "resource:///modules/gloda/GlodaDatastore.jsm" line: 1281}]
shutdown@resource:///modules/gloda/GlodaDatastore.jsm:1281:7
_shutdown@resource:///modules/gloda/GlodaIndexer.jsm:412:20
observe@resource:///modules/gloda/GlodaIndexer.jsm:1482:12
@/NEW-SSD/moz-obj-dir/objdir-tb3/_tests/xpcshell/comm/mail/components/extensions/test/xpcshell/test_ext_messages_query.js:221:16
_execute_test/<@/NEW-SSD/NREF-COMM-CENTRAL/mozilla/testing/xpcshell/head.js:641:28
async*_execute_test@/NEW-SSD/NREF-COMM-CENTRAL/mozilla/testing/xpcshell/head.js:650:5
@-e:1:1
"
 0:46.58 pid:1186774 {streamdebug} closing: folderCache (= 0x55f260956260 )->Close() 'before possible Close' in WriteToFolderCache  at line 1516 of /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgAccountManager.cpp
 0:47.06 pid:1186774 [1186774, Main Thread] WARNING: some msg dbs left open: '!m_dbCache.Length()', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgDatabase.cpp, line 80
 0:47.71 pid:1186774 [1186774, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsCycleCollector.cpp, line 3359
 0:47.75 pid:1186774 [1186774, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsTraceRefcnt.cpp, line 202
 0:47.75 pid:1186774 [1186774, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsTraceRefcnt.cpp, line 202
 0:47.75 pid:1186774 nsStringStats

The code in question was touched by a patch in bug 465122.
The discussion there may shed some light on this issue.