Open Bug 1535993 Opened 4 years ago Updated 4 months ago

|make mozmill| produces 300+ WARNINGS of the form WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 666

Categories

(MailNews Core :: Backend, defect)

Product:
MailNews Core
Component:
Backend
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

People

(Reporter: ishikawa, Assigned: ishikawa)

References

Details

Attachments

(1 file, 1 obsolete file)

Updated patch to dump some key information for debugging.
10.04 KB, text/plain
Details

I run FULL DEBUG build of TB under local linux (amd64) PC for testing.

During |make mozmill| testing, many WARNINGS/ERRORS and even ASSERTIONS are produced today.

See the latest list of such warnings/errors/assertions in https://groups.google.com/forum/#!topic/mozilla.dev.apps.thunderbird/LgIlm9dhCkM

Among the warnings, Jorg singled out the following as eye-catching for thunderbird developres.

293: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 666
293: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5132

Attached patch chasing-strange-db-errors.patch (obsolete) — — Splinter Review

This is the patch to print |uri| that is passed to |MessageURIToMsgHdr(), and also where the errors occur in related functions.

Assignee: nobody → ishikawa

After capturing the log in /tmp/log1016-mozmill.txt, I ran the following command to try to figure out the patterns of the errors.

egrep "(#[0-9]+|ASSERTION|^TEST-|GetMsgDatabase|number)" /FF-NEW/log1016-mozmill.txt | grep -v "^#"

I realized that all the errors seem to be generated by uri which ends with "display&number=0#0"

For exampple,

TEST-START | /NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/test-attachment-in-plain-msg.js | test_attachment_not_empty
{debug}: nsMailboxService::MessageURIToMsgHdr:uri=mailbox-message:///NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/bug1358565.eml?type=application/x-message-display&number=0#0
{debug}: nsMsgLocalMailFolder::OpenDatabase() parent was null after GetParent(getter_AddRefs(parent)
[26912, Main Thread] ###!!! ASSERTION: GetMsgDatabase(getter_AddRefs(database)) returned failure.: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5139
[26912, Main Thread] ###!!! ASSERTION: GetMessageHeader(msgKey, _retval) returned failure: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 675
{debug}: nsMailboxService::MessageURIToMsgHdr:uri=mailbox-message:///NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/bug1358565.eml?type=application/x-message-display&number=0#0
{debug}: nsMsgLocalMailFolder::OpenDatabase() parent was null after GetParent(getter_AddRefs(parent)
[26912, Main Thread] ###!!! ASSERTION: GetMsgDatabase(getter_AddRefs(database)) returned failure.: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5139
[26912, Main Thread] ###!!! ASSERTION: GetMessageHeader(msgKey, _retval) returned failure: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 675
{debug}: nsMailboxService::MessageURIToMsgHdr:uri=mailbox-message:///NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/bug1358565.eml?type=application/x-message-display&number=0#0
{debug}: nsMsgLocalMailFolder::OpenDatabase() parent was null after GetParent(getter_AddRefs(parent)
[26912, Main Thread] ###!!! ASSERTION: GetMsgDatabase(getter_AddRefs(database)) returned failure.: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5139
[26912, Main Thread] ###!!! ASSERTION: GetMessageHeader(msgKey, _retval) returned failure: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 675

Does this ring a bell?

I notice that there are mixture of mailbox:/// URIs and mailbox-message:/// URIs.

See for example,
--DOMWINDOW == 137 (0x564def663d50) [pid = 26912] [serial = 111] [outer = (nil)] [url = mailbox:///NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/bug1358565.eml?type=application/x-message-display&number=0]

Yesterday, I refreshed the source files and reran the test.

I still get these.
305: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 677
305: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5142

With the patch to dump the related variables, I got the following log.
It seems that opening fails with missing summary file.

Has there been a change of logic to either delay or not create summary file on demand?
That is, is it possible that an explicit action is now required to create the summary file in the face of missing summary file
whereas the summary file was created when it was necessary automagically before???)

A case in point:

TEST-START | /NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/test-attachment-in-plain-msg.js | test_attachment_not_empty
++DOCSHELL 0x5617da5cd5d0 == 44 [pid = 29212] [id = {878d6847-030e-44d4-968c-ef40d6d127e1}]
++DOMWINDOW == 101 (0x5617dadb0160) [pid = 29212] [serial = 109] [outer = (nil)]

        ... some DOCSHELL and DOMWINDOW lines are deleted.

++DOMWINDOW == 98 (0x5617d9e53d00) [pid = 29212] [serial = 112] [outer = (nil)]
[29212, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /NREF-COMM-CENTRAL/mozilla/layout/base/nsDocumentViewer.cpp, line 3124
++DOMWINDOW == 99 (0x5617db37e840) [pid = 29212] [serial = 113] [outer = 0x5617da01ebf0]
++DOMWINDOW == 100 (0x5617d9eab040) [pid = 29212] [serial = 114] [outer = 0x5617d9e53d00]
++DOMWINDOW == 101 (0x5617d9dfd5a0) [pid = 29212] [serial = 115] [outer = 0x5617da01ebf0]
[29212, Main Thread] WARNING: '!ClientIsValidPrincipalInfo(mClientInfo.PrincipalInfo())', file /NREF-COMM-CENTRAL/mozilla/dom/clients/manager/ClientSource.cpp, line 169
{debug}: nsMailboxService::MessageURIToMsgHdr:uri=mailbox-message:///NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/bug1358565.eml?type=application/x-message-display&number=0#0
{debug}: msgKey=0
{debug}: nsMsgLocalMailFolder::GetDatabaseWOReparse(nsIMsgDatabase aDatabase) - mDdatabase = 0x(nil)
{debug}: mDatabase = 0x(nil) on etry to nsMsgLocalMailFolder::OpenDatabase()
{debug}: nsMsgLocalMailFolder::OpenDatabase() rv = msgDBService->OpenFolderDB(this, true, getter_AddRefs(mDatabase)):
rv = 0x80550006 == NS_MSG_ERROR_FOLDER_SUMMARY_MISSING (=0x80550006)
{debug}: nsMsgLocalMailFolder::OpenDatabase() parent was null after GetParent(getter_AddRefs(parent)
{debug}: after the call to OpenDatabase() - mDdatabase = 0x(nil)
msgKey = 0
[29212, Main Thread] ###!!! ASSERTION: GetMsgDatabase(getter_AddRefs(database)) returned failure.: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5139
#01: nsMsgDBFolder::GetMessageHeader(unsigned int, nsIMsgDBHdr) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp:5139 (discriminator 1))
#02: nsMailboxService::MessageURIToMsgHdr(char const*, nsIMsgDBHdr**) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp:673)
#03: GetMsgDBHdrFromURI(char const*, nsIMsgDBHdr**) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgUtils.cpp:172)
#04: nsMailboxUrl::GetFolder(nsIMsgFolder**) (/KERNEL-SRC/moz-obj-dir/objdir-tb3/dist/include/nsCOMPtr.h:1289)
#05: nsMailboxUrl::GetFolderCharset(char**) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxUrl.cpp:526)
#06: bridge_new_new_uri(void*, nsIURI*, int) (/KERNEL-SRC/moz-obj-dir/objdir-tb3/dist/include/nsTString.h:684)
#07: nsStreamConverter::SetStreamURI(nsIURI*) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/mime/src/nsStreamConverter.cpp:723)
#08: nsStreamConverter::Init(nsIURI*, nsIStreamListener*, nsIChannel*) (/KERNEL-SRC/moz-obj-dir/objdir-tb3/dist/include/nsCOMPtr.h:839)
#09: nsStreamConverter::AsyncConvertData(char const*, char const*, nsIStreamListener*, nsISupports*) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/mime/src/nsStreamConverter.cpp:1132)
#10: nsStreamConverterService::AsyncConvertData(char const*, char const*, nsIStreamListener*, nsISupports*, nsIStreamListener**) (/NREF-COMM-CENTRAL/mozilla/netwerk/streamconv/nsStreamConverterService.cpp:513)
#11: mozilla::mailnews::MailNewsDLF::CreateInstance(char const*, nsIChannel*, nsILoadGroup*, nsTSubstring<char> const&, nsIDocShell*, nsISupports*, nsIStreamListener**, nsIContentViewer**) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/MailNewsDLF.cpp:80)
#12: nsDocShell::NewContentViewerObj(nsTSubstring<char> const&, nsIRequest*, nsILoadGroup*, nsIStreamListener**, nsIContentViewer**) (/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDocShell.cpp:8207)
#13: nsDocShell::CreateContentViewer(nsTSubstring<char> const&, nsIRequest*, nsIStreamListener**) (/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDocShell.cpp:7996)
#14: nsDSURIContentListener::DoContent(nsTSubstring<char> const&, bool, nsIRequest*, nsIStreamListener**, bool*) (/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDSURIContentListener.cpp:182)
#15: nsDocumentOpenInfo::TryContentListener(nsIURIContentListener*, nsIChannel*) (/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsURILoader.cpp:749)
#16: nsDocumentOpenInfo::DispatchContent(nsIRequest*, nsISupports*) (/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsURILoader.cpp:420)
#17: nsDocumentOpenInfo::OnStartRequest(nsIRequest*) (/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsURILoader.cpp:299)
#18: nsMsgProtocol::OnStartRequest(nsIRequest*) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgProtocol.cpp:328)
#19: nsMailboxProtocol::OnStartRequest(nsIRequest*) (/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxProtocol.cpp:232)
#20: nsInputStreamPump::OnStateStart() (/NREF-COMM-CENTRAL/mozilla/netwerk/base/nsInputStreamPump.cpp:487)
#21: nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) (/NREF-COMM-CENTRAL/mozilla/netwerk/base/nsInputStreamPump.cpp:396)
#22: mozilla::SlicedInputStream::OnInputStreamReady(nsIAsyncInputStream*) (/NREF-COMM-CENTRAL/mozilla/xpcom/io/SlicedInputStream.cpp:414)
#23: nsInputStreamReadyEvent::Run() (/NREF-COMM-CENTRAL/mozilla/xpcom/io/nsStreamUtils.cpp:175)
#24: nsThread::ProcessNextEvent(bool, bool*) (/NREF-COMM-CENTRAL/mozilla/xpcom/threads/nsThread.cpp:1184)
#25: NS_InvokeByIndex (/NREF-COMM-CENTRAL/mozilla/xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:110)
#26: XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) (/NREF-COMM-CENTRAL/mozilla/js/xpconnect/src/XPCWrappedNative.cpp:1178)
#27: XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) (/NREF-COMM-CENTRAL/mozilla/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:941)
#28: ??? (???:???)
[29212, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5142

Ready for review? Or do we need to direct a question to someone?

Component: Untriaged → Backend
Flags: needinfo?(ishikawa)
Product: Thunderbird → MailNews Core

(In reply to Wayne Mery (:wsmwk) from comment #5)

Ready for review? Or do we need to direct a question to someone?

I think we ought to ask someone if the timing of summary file generation has changed in the last several months.

I am not sure, though, if the error can be ignored. It looks serious.

Flags: needinfo?(ishikawa)

Start with aceman? (Or Ben?)

Flags: needinfo?(acelists)
Version: unspecified → 68
Comment on attachment 9051605 [details] [diff] [review]
chasing-strange-db-errors.patch

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

Hi, thanks for looking into this.
The patch adds a lot of debugging output, but does it solve the problems? Have you identified when the errors in the console happen and how to solve them gracefully in the core without returning a failure 'rv' and triggering the warning in console?

(In reply to ISHIKAWA, Chiaki from comment #6)

I think we ought to ask someone if the timing of summary file generation has changed in the last several months.

Probably not intentionally, but we made some changes (like removing RDF from fetching folder references, and some folder URI changes forced from m-c), which could slightly affect the timing. Does it cause any case where the .msg database is not created when it should?

Flags: needinfo?(acelists)
Summary: |make mozmill| produces 300- WARINNGS of the form WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 666 → |make mozmill| produces 300+ WARNINGS of the form WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 666

Do these errors show in any Mozmill or Xpcshell logs in automation? Do they still show up locally. We've reformatted the entire tree since March, so I suspect the line numbers have changed. Is there a specific action that causes those errors. We can't run an entire test suite and then try to analyse 300+ warnings.

correlates to your work in bug 617945?

Flags: needinfo?(ishikawa)

(In reply to Wayne Mery (:wsmwk) from comment #11)

correlates to your work in bug 617945?

Good catch.

I will investigate some lines related to the bug mentioned here.
I think the timing must have changed to the point we see some errors.

See Also: → 617945

(In reply to Jorg K (CEST = GMT+2) from comment #10)

Do these errors show in any Mozmill or Xpcshell logs in automation? Do they still show up locally. We've reformatted the entire tree since March, so I suspect the line numbers have changed. Is there a specific action that causes those errors. We can't run an entire test suite and then try to analyse 300+ warnings.

They still do.
The line numbers have changed, though, on the try-comm-central.

293: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp, line 666

The line above is now at
https://searchfox.org/comm-central/source/mailnews/local/src/nsMailboxService.cpp#626

293: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/util/nsMsgDBFolder.cpp, line 5132

The above is now at https://searchfox.org/comm-central/source/mailnews/base/src/nsMsgDBFolder.cpp#4525

They still appear in my local jobs, and my try-comm-central jobs.
In other people's jobs as well.: See for example
mkmelin's job. March 22. Take a look at bct3 log, for example.
https://treeherder.mozilla.org/logviewer?job_id=333962245&repo=try-comm-central&lineNumber=5416

Flags: needinfo?(ishikawa)

Interesting observation.

I was checking |OpenDatabase()| behavior because
the failure of |GetMessageHeader(msgKey, _retval)| on
https://searchfox.org/comm-central/source/mailnews/local/src/nsMailboxService.cpp#626
and |nsresult rv = GetMsgDatabase(getter_AddRefs(database))|
on https://searchfox.org/comm-central/source/mailnews/base/src/nsMsgDBFolder.cpp#4525
can be traced to the failure of |OpenDatabase()| one way or the other.

OpenDatabase() is here.:
https://searchfox.org/comm-central/source/mailnews/local/src/nsLocalMailFolder.cpp#827

Interesting observation.

OpenDatabase() is called 2662 times during mochitest of TB. And mDatabase is always null upon entry.
So this call is supposed to create an object and set mDatabase to its address.

Problem is that many times, the mDatabase is not set to non-null value (i.e., remains nullptr).

Why?
To wit, I see that due to the failure (?) of GetParent(), |parent| is null 747 times during mochitest execution.
|mDatabase| remains null in such cases, and OpenDatabase() returns.

Of course, not all the errors as such are related to the many warnings observed because I see only 246 such warnings in my
local run. (Note the different line numbers because of the addition of printf() dumps.)

246: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp:637

246: Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80550006: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgDBFolder.cpp:4538

There are probably other factors that mitigate the errors in the calling functions such as |GetMessageHeader(msgKey, _retval)| and
|GetMsgDatabase()|.

But I think we need to figure out why OpenDatabase() returns with null |mDataBase()|.

What does GetParent() do? The code is a bit mysterious.

What is the easiest way to print the file path name that would be searched and opened by TB from |OpenDatabase()|?

These are the question and one debug aid I can think of right now.

This is an updated patch to print key information for debugging which I have been using for some time.
(I am cleaning up my local patch queue for buffered output and this patch gets in the way for now and so
am removing from my local patch queue temporarily. Someone may find it useful to track down the
issue of strange errors reported in debug build.)

Attachment #9051605 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.