1674077 - debug perma - Assertion failure: NS_IsMainThread() - application crashed [@ nsStringBundle::LoadProperties() - comm/mail/base/test/unit/test_emptyTrash_dbViewWrapper.js, comm/mailnews/imap/test/unit/test_imapFilterActions.js and others

Status: RESOLVED FIXED

(MailNews Core :: Backend, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: mkmelin+mozilla [at] iki.fi
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=320070268&repo=comm-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dUlifXf9TgiJZKRyw89sTw/runs/0/artifacts/public/logs/live_backing.log

---

Comment 1

[Magnus Melin [:mkmelin]]

Turned up first with https://treeherder.mozilla.org/#/jobs?repo=comm-central&selectedTaskRun=L4cDVS8kT4aKAYb3cEGCNg.0&revision=e48d3c359bcd9cda2b954c9b0de1cc5d486d0879

Comment 2

[Magnus Melin [:mkmelin]]

I think these are all related:

TEST-UNEXPECTED-FAIL | comm/mail/base/test/unit/test_emptyTrash_dbViewWrapper.js | xpcshell return code: -11
Logviewer
Assertion failure: NS_IsMainThread(), at /builds/worker/workspace/obj-build/dist/include/mozilla/ClearOnShutdown.h:133
Logviewer
PROCESS-CRASH | comm/mail/base/test/unit/test_emptyTrash_dbViewWrapper.js | application crashed [@ nsStringBundle::LoadProperties()]
Logviewer
TEST-UNEXPECTED-FAIL | comm/mail/base/test/unit/test_viewWrapper_imapFolder.js | xpcshell return code: -11
Logviewer
Assertion failure: NS_IsMainThread(), at /builds/worker/workspace/obj-build/dist/include/mozilla/ClearOnShutdown.h:133
Logviewer
PROCESS-CRASH | comm/mail/base/test/unit/test_viewWrapper_imapFolder.js | application crashed [@ nsStringBundle::LoadProperties()]
Logviewer
TEST-UNEXPECTED-FAIL | comm/mail/base/test/unit/test_viewWrapper_virtualFolderCustomTerm.js | xpcshell return code: -11
Logviewer
Assertion failure: NS_IsMainThread(), at /builds/worker/workspace/obj-build/dist/include/mozilla/ClearOnShutdown.h:133
Logviewer
PROCESS-CRASH | comm/mail/base/test/unit/test_viewWrapper_virtualFolderCustomTerm.js | application crashed [@ nsStringBundle::LoadProperties()]
Logviewer

Comment 3

[Magnus Melin [:mkmelin]]

Test is ok locally on c-c tip (with m-c not updated), so likely something from https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=9b78e4ae32ae9fe7a22b4bb15efb51251d70c5e6

Comment 4

[Magnus Melin [:mkmelin]]

Also TEST-UNEXPECTED-FAIL | xpcshell-imap.ini:comm/mail/components/extensions/test/xpcshell/test_ext_experiments.js | xpcshell return code: -11

Comment 5

[Magnus Melin [:mkmelin]]

[task 2020-10-28T23:22:53.625Z] 23:22:53 INFO - PID 26434 | Assertion failure: NS_IsMainThread(), at /builds/worker/workspace/obj-build/dist/include/mozilla/ClearOnShutdown.h:133
[task 2020-10-28T23:22:53.625Z] 23:22:53 INFO - PID 26434 | #01: nsStringBundle::GetStringImpl(nsTSubstring<char> const&, nsTSubstring<char16_t>&) [intl/strres/nsStringBundle.cpp:573]
[task 2020-10-28T23:22:53.626Z] 23:22:53 INFO - PID 26434 | #02: nsStringBundleBase::GetStringFromName(char const*, nsTSubstring<char16_t>&) [intl/strres/nsStringBundle.cpp:568]
[task 2020-10-28T23:22:53.626Z] 23:22:53 INFO - PID 26434 | #03: nsStringBundleBase::FormatStringFromName(char const*, nsTArray<nsTString<char16_t> > const&, nsTSubstring<char16_t>&) [intl/strres/nsStringBundle.cpp:617]
[task 2020-10-28T23:22:53.626Z] 23:22:53 INFO - PID 26434 | #04: nsImapProtocol::ShowProgress() [comm/mailnews/imap/src/nsImapProtocol.cpp:5167]
[task 2020-10-28T23:22:53.627Z] 23:22:53 INFO - PID 26434 | #05: nsImapServerResponseParser::msg_fetch() [comm/mailnews/imap/src/nsImapServerResponseParser.cpp:939]
[task 2020-10-28T23:22:53.627Z] 23:22:53 INFO - PID 26434 | #06: nsImapServerResponseParser::response_data() [comm/mailnews/imap/src/nsImapServerResponseParser.cpp:659]
[task 2020-10-28T23:22:53.628Z] 23:22:53 INFO - PID 26434 | #07: nsImapServerResponseParser::ParseIMAPServerResponse(char const*, bool, char*) [comm/mailnews/imap/src/nsImapServerResponseParser.cpp:190]
[task 2020-10-28T23:22:53.628Z] 23:22:53 INFO - PID 26434 | #08: nsImapProtocol::FetchMessage(nsTString<char> const&, nsIMAPeFetchFields, char const*, unsigned int, unsigned int, char*) [comm/mailnews/imap/src/nsImapProtocol.cpp:3647]
[task 2020-10-28T23:22:53.629Z] 23:22:53 INFO - PID 26434 | #09: nsImapProtocol::FolderMsgDumpLoop(unsigned int*, unsigned int, nsIMAPeFetchFields) [comm/mailnews/imap/src/nsImapProtocol.cpp:4416]
[task 2020-10-28T23:22:53.630Z] 23:22:53 INFO - PID 26434 | #10: nsImapProtocol::ProcessMailboxUpdate(bool) [comm/mailnews/imap/src/nsImapProtocol.cpp:4299]
[task 2020-10-28T23:22:53.630Z] 23:22:53 INFO - PID 26434 | #11: nsImapProtocol::ProcessSelectedStateURL() [comm/mailnews/imap/src/nsImapProtocol.cpp:3135]
[task 2020-10-28T23:22:53.630Z] 23:22:53 INFO - PID 26434 | #12: nsImapProtocol::ProcessCurrentURL() [comm/mailnews/imap/src/nsImapProtocol.cpp:1798]
[task 2020-10-28T23:22:53.631Z] 23:22:53 INFO - PID 26434 | #13: nsImapProtocol::ImapThreadMainLoop() [comm/mailnews/imap/src/nsImapProtocol.cpp:1439]
[task 2020-10-28T23:22:53.631Z] 23:22:53 INFO - PID 26434 | #14: nsImapProtocol::Run() [comm/mailnews/imap/src/nsImapProtocol.cpp:1124]
[task 2020-10-28T23:22:53.632Z] 23:22:53 INFO - PID 26434 | #15: {virtual override thunk({offset(-8)}, nsImapProtocol::Run())} [/builds/worker/workspace/build/application/thunderbird/libxul.so + 0x4500805]
[task 2020-10-28T23:22:53.632Z] 23:22:53 INFO - PID 26434 | #16: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1197]
[task 2020-10-28T23:22:53.632Z] 23:22:53 INFO - PID 26434 | #17: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:513]
[task 2020-10-28T23:22:53.632Z] 23:22:53 INFO - PID 26434 | #18: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:303]
[task 2020-10-28T23:22:53.633Z] 23:22:53 INFO - PID 26434 | #19: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:334]
[task 2020-10-28T23:22:53.633Z] 23:22:53 INFO - PID 26434 | #20: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:310]
[task 2020-10-28T23:22:53.633Z] 23:22:53 INFO - PID 26434 | #21: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:444]
[task 2020-10-28T23:22:53.636Z] 23:22:53 INFO - PID 26434 | #22: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]

Comment 6

[Magnus Melin [:mkmelin]]

Hmm, since it's debug only, can also be from https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=83bf4fd3b1fbca9dcbe23de9d1a1503eed62569a

Comment 7

[Magnus Melin [:mkmelin]]

Must be from this: https://hg.mozilla.org/mozilla-central/rev/83bf4fd3b1fbca9dcbe23de9d1a1503eed62569a (bug 1667613)
Not sure if we're doing something wrong in IMAP or just not handling the (new) error as expected.

Comment 8

[Magnus Melin [:mkmelin]]

Ben, please check what needs doing here.

Comment 9

[Ben Campbell]

First impressions: It's a new bug introduced by the patch in Bug 1667613.

It's crashing because the IMAP logic is updating a progress message, and calls nsIStringBundle.formatStringFromName() which eventually calls PastShutdownPhase(), which asserts if we're not on the main thread.

I think this assert is wrong. My impression is that while nsIStringBundles must be created on the main thread, you're allowed to use them from other threads. The nsStringBundle implementation has a mutex to handle this and everything.

I_think_ the correct fix is for PastShutdownPhase() to be made threadsafe.
I guess this would entail protecting sCurrentShutdownPhase with a mutex (I'm happy to try doing this after the weekend).

PastShutdownPhase() was added recently in Bug 1663747. A lot of the other functions in ClearOnShutdown have a similar main-thread assertion, which is fine - most of those functions are mainthread-only. But the not-allowed-to-use-stringbundles-during shutdown rule added in Bug 1667613 seems entirely reasonable, and that implies being able to access the shutdown phase off the main thread. So stringbundles need a threadsafe PastShutdownPhase().

There's also a big elephant in the room: It seems awfully icky for the guts of the IMAP to be looking up strings for the GUI anyway! While I think PastShutdownPhase() should be threadsafe, I also think we should be purging GUIsms like this from our protocol code.

Comment 10

[Magnus Melin [:mkmelin]]

m_kato, what do you think about comment 9?

Comment 11

[Makoto Kato [:m_kato]]

string bundle is XPCOM object and scriptable. Why does thunderbird use this on non-main thread?

Comment 12

[Intermittent Failures Robot]

15 failures in 4275 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 15

Platform breakdown:

• linux64: 3
• windows10-64: 4
• windows7-32: 6
• macosx1014-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1674077&startday=2020-10-26&endday=2020-11-01&tree=all

Comment 13

[Ben Campbell]

(In reply to Makoto Kato [:m_kato] from comment #11)

string bundle is XPCOM object and scriptable.

Exposing my XPCOM-ignorance there, I think. To be honest I don't really know the exact restrictions that XPCOM and scriptable entail. I'm aware that in general it's frowned upon to use them off the main thread... but I wasn't sure how rigid that is (there's lots of historical TB-specific XPCOM stuff which is used cross-thread).
The stringbundle implementation seems to suggest they can be used off the main thread (as long as they are still created on the main thread):

https://searchfox.org/mozilla-central/search?q=thread&path=nsStringBundle.*&case=false&regexp=false

Why does thunderbird use this on non-main thread?

I'm not going to defend thunderbird at all here :-) For historical reasons there are a bunch of places down in the plumbing which poke the GUI in ways more direct than I'd really like. This is one of them, made worse by the fact it's on another thread.

Comment 14

[Ben Campbell]

Attachment: 1674077-move-imap-stringbundle-access-to-main-thread-1.patch

Anyway, independent of whether or not it's valid to access stringbundle from off the main thread, here's a patch which should fix things.
It moves the stringbundle access out into the folder code. Still not quite as decoupled from the protocol layer as I'd like (that'd involve a big overhaul of the whole progress-communicating system(s)), but a step in the right direction at least.

Comment 15

[Magnus Melin [:mkmelin]]

Comment on attachment 9185086 [details] [diff] [review]
1674077-move-imap-stringbundle-access-to-main-thread-1.patch

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

::: mailnews/imap/public/nsIImapMailFolderSink.idl
@@ +106,5 @@
>    void headerFetchCompleted(in nsIImapProtocol aProtocol);
>    void setBiffStateAndUpdate(in long biffState);
>    void progressStatusString(in nsIImapProtocol aProtocol, in string aMsgId, in wstring extraInfo);
> +  void percentProgress(in nsIImapProtocol aProtocol,
> +                       in ACString aFmtStringName, in AString aMailboxName,

A bit odd to have mixed string types in the idl.
Maybe both should be AUTF8String?

I would have thought this interface knows about the folder name, but apparently not...

Comment 16

[Ben Campbell]

(In reply to Magnus Melin [:mkmelin] from comment #15)

> Review of attachment 9185086:
> -----------------------------------------------------------------
> 
> ::: mailnews/imap/public/nsIImapMailFolderSink.idl
> > +  void percentProgress(in nsIImapProtocol aProtocol,
> > +                       in ACString aFmtStringName, in AString aMailboxName,
> 
> A bit odd to have mixed string types in the idl.

Agreed, and I umm-ed and err-ed about it for a while, but I think the types are fine (it's just the interface as a whole which is screwed up ;- )

aFmtStringName is the name of the (localised) format string to look up in the bundle. Essentially a key, in ASCII.

aMailboxName, aCurrentProgress and aMaxProgress are parameters required to expand that format string. The formatting generates an AString, so it seems right that the string params (Mailbox) is also an AString.

Maybe both should be AUTF8String?

I think all strings should be passed in AUTF8String :-)

I would have thought this interface knows about the folder name, but
apparently not...

Well, the ultimate destination (an nsImapMailFolder) probably does know the mailbox name: the onlineName attr.
I don't think the folder would ever be given progress updates for another mailbox, but I'm not 100% sure on this. I've seen odder things.
The best argument for keeping the mailbox name as a parameter for now is that the format string expects three parameters (mailboxname, currentprogress, maxprogress), and it seems cleaner to pass them all along together.

What Should Happen (tm):

The progress interface shouldn't be passing the formatstring name, or any kind of string-based stuff at all. It should just tell the listener what's happening, along with whatever data the listener needs to compose a decent progress message itself. This probably means changing the interface to pass out an enum to say what the current operation is, rather than the formatstring name. Still need currentProgress and maxProgress params, but might not need the mailbox name.

Comment 17

[Magnus Melin [:mkmelin]]

Comment on attachment 9185086 [details] [diff] [review]
1674077-move-imap-stringbundle-access-to-main-thread-1.patch

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

Alright, let's take this

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/f00c821955a9
Move IMAP GUI stringbundle access to main thread. r=mkmelin

Comment 19

[Intermittent Failures Robot]

32 failures in 4128 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #47 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• comm-central: 32

Platform breakdown:

• linux64: 12
• macosx1014-64: 9
• windows7-32: 5
• windows10-64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1674077&startday=2020-11-02&endday=2020-11-08&tree=all