Closed Bug 1298081 Opened 8 years ago Closed 8 years ago

TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed

Categories

(Thunderbird :: Message Compose Window, defect)

51 Branch
x86
Linux
defect
Not set
normal

Tracking

(thunderbird50 fixed, thunderbird51 fixed, thunderbird52 fixed)

RESOLVED FIXED
Thunderbird 52.0
Tracking Status
thunderbird50 --- fixed
thunderbird51 --- fixed
thunderbird52 --- fixed

People

(Reporter: aleth, Assigned: alta88)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Frequent Linux mozmill failure in composition/test-attachment-reminder.js. 

Issues visible in the log:
NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
Call to GetDiskSpaceAvailable FAILED!

 08:01:03     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | setupModule
 08:01:03     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::setupModule
 08:01:03     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_reminder_appears_properly
 08:01:03     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_reminder_appears_properly
 08:01:03     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_reminder_dismissal
 08:01:03     INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
 08:01:27     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_reminder_dismissal
 08:01:27     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_reminder_with_attachment
 08:01:27     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_reminder_with_attachment
 08:01:27     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_reminder_aggressive_pref
 08:01:27     INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
 08:01:35     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_reminder_aggressive_pref
 08:01:35     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_no_send_now_sends
 08:01:35     INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
 08:01:50     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_no_send_now_sends
 08:01:50     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_manual_attachment_reminder
 08:01:50     INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
 08:02:22     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_manual_attachment_reminder
 08:02:22     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_manual_automatic_attachment_reminder_interaction
 08:02:22     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_manual_automatic_attachment_reminder_interaction
 08:02:22     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_vs_filelink_reminder
 08:02:22     INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
 08:02:51     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_vs_filelink_reminder
 08:02:51     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_reminder_in_subject
 08:02:51     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_reminder_in_subject
 08:02:51     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_attachment_reminder_in_subject_and_body
 08:02:51     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_attachment_reminder_in_subject_and_body
 08:02:51     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_disabled_attachment_reminder
 08:02:51     INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
 08:03:24     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_disabled_attachment_reminder
 08:03:24     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_reminder_in_draft
 08:03:24     INFO -  TEST-PASS | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test-attachment-reminder.js::test_reminder_in_draft
 08:03:24     INFO -  TEST-START | /builds/slave/test/build/tests/mozmill/composition/test-attachment-reminder.js | test_disabling_attachment_reminder
 08:03:24     INFO -  Call to GetDiskSpaceAvailable FAILED!
 08:04:20     INFO -  Timeout: bridge.execFunction("d3f75e28-6ad3-11e6-97f6-0295c70f58c7", bridge.registry["{b4a6d06e-79c7-4969-9bdf-a67e8e016f7a}"]["runTestDirectory"], ["/builds/slave/test/build/tests/mozmill/composition"])
08:04:20 WARNING - TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed
(In reply to aleth [:aleth] from comment #0)
> Call to GetDiskSpaceAvailable FAILED!

This error message comes from nsMsgLocalStoreUtils::DiskSpaceAvailableInStore in nsMsgLocalStoreUtils.cpp.
(In reply to aleth [:aleth] from comment #0)
> NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff
> (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]

server is the nsMsgIncomingServer.

Didn't someone recently touch this stuff via the account manager?
Flags: needinfo?(acelists)
32b Linux only, not 64b?
Hardware: Unspecified → x86
(In reply to aleth [:aleth] from comment #1)
> (In reply to aleth [:aleth] from comment #0)
> > Call to GetDiskSpaceAvailable FAILED!
> 
> This error message comes from
> nsMsgLocalStoreUtils::DiskSpaceAvailableInStore in nsMsgLocalStoreUtils.cpp.

Yes, this one is strange. It should not fail on sane platforms. Unless we query it with an invalid nsIFile.

Is this one found in each of the runs that fail?

(In reply to aleth [:aleth] from comment #2)
> (In reply to aleth [:aleth] from comment #0)
> > NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff
> > (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
> 
> server is the nsMsgIncomingServer.
> 
> Didn't someone recently touch this stuff via the account manager?

This seems to be some error from the activity manager. It does not seem to affect the tests and does not cause them to fail. Unless it is an indication of some problem that we do not have a proper server defined the alertHook.js comments indicate that file is for the "send later" function.

I can check that out.
Assignee: nobody → acelists
My debug output on try run:
https://archive.mozilla.org/pub/thunderbird/try-builds/acelists@atlas.sk-f3341a556007/try-comm-central-linux-debug/try-comm-central_ubuntu32_vm-debug_test-mozmill-bm05-tests1-linux32-build0.txt.gz

00:56:44     INFO -  ERROR: GetDiskSpaceAvailable: STATFS call FAILED.
00:56:44     INFO -  Call to GetDiskSpaceAvailable FAILED!
00:56:44     INFO -  ACE: 0, e=0, file=/builds/slave/test/build/tests/mozmill/mozmillprofile/Mail/Local Folders/Unsent Messages

It seems the GetDiskSpaceAvailable() fails because the file for "Unsent Messages" does not exist.

In that failing test we Send a message "later" which should copy it to Unsent Messages. Any msg copy into a folder first checks if there is enough space in the folder/disk. As this may be the first access to the folder in that test profile, the nsIMsgFolder for it is created, but the backing file (store) is not created immediately (maybe after first write of some msg into it).

So I have to make sure the file exists when we try to query disk space on it. I'll see if that fixes the problem.

But I wonder why this crashes the test (it should just refuse to store the msg in the folder). Maybe unfulfilled waiting for an expected dialog (or compose closure) takes down the mozmill session after the timeout.

Also I wonder why this wasn't a problem before.
Flags: needinfo?(acelists)
(In reply to :aceman from comment #6)

Thanks for looking into this!

> So I have to make sure the file exists when we try to query disk space on
> it. I'll see if that fixes the problem.
> 
> But I wonder why this crashes the test (it should just refuse to store the
> msg in the folder). Maybe unfulfilled waiting for an expected dialog (or
> compose closure) takes down the mozmill session after the timeout.
> 
> Also I wonder why this wasn't a problem before.

Sounds like a timing issue where something is now faster/slower than before, revealing a problem? Maybe those build machines got some update installed or something...
(In reply to :aceman from comment #6)

> 
> Also I wonder why this wasn't a problem before.

INFO -  JavaScript error: resource:///modules/activity/alertHook.js, line 48: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]

This may not have been a problem before, but at least
this error message has been around for quite some time on my local test PC's log.
For example, it is found in a log from July 2013.
(Presumably older log also has it.)

I was assuming this was a fluke on my PC since nobody seems to make a great issue out of this until now.

BTW, long time ago, maybe 2012 time frame(?) someone mentioned that an additional function to the alertHook.js should fix this or other issues which were noticed back then, but I was a newbie to the code base and did not understand the implications of the discussion at all.


Another observation:
(In reply to :aceman from comment #6)

> 
> But I wonder why this crashes the test (it should just refuse to store the
> msg in the folder). Maybe unfulfilled waiting for an expected dialog (or
> compose closure) takes down the mozmill session after the timeout.
> 

This is possibly the case.
I run local test under linux.

There is a time during mozmill session when TB fails to send out something (maybe a large attachment that is passed by a file transfer service).
But it fails to do so, and I see there is a dialog shown on the screen regarding the failure until the timeout kicks in and the next test begins to execute.

TIA
(In reply to ISHIKAWA, Chiaki from comment #8)
> (In reply to :aceman from comment #6)
> > 
> > But I wonder why this crashes the test (it should just refuse to store the
> > msg in the folder). Maybe unfulfilled waiting for an expected dialog (or
> > compose closure) takes down the mozmill session after the timeout.
> > 
> 
> This is possibly the case.
> I run local test under linux.
> 

this is always the case, under linux, running locally. it is due to Outbox being removed by test-charset-upgrade.js teardownModule() and not being ready in time for the next test needing it; ie it works when those lines are removed.  by works, it means composition mozmill-one failures drop from 10 to 9 and there's no disk space dialog.
(In reply to alta88 from comment #9)
> (In reply to ISHIKAWA, Chiaki from comment #8)
> > (In reply to :aceman from comment #6)
> > > 
> > > But I wonder why this crashes the test (it should just refuse to store the
> > > msg in the folder). Maybe unfulfilled waiting for an expected dialog (or
> > > compose closure) takes down the mozmill session after the timeout.
> > > 
> > 
> > This is possibly the case.
> > I run local test under linux.
> > 
> 
> this is always the case, under linux, running locally. it is due to Outbox
> being removed by test-charset-upgrade.js teardownModule() and not being
> ready in time for the next test needing it; ie it works when those lines are
> removed.  by works, it means composition mozmill-one failures drop from 10
> to 9 and there's no disk space dialog.

Wow. Thank you for the explanation. I should have known.
Can we rewrite the test so that this timeout is not observed under linux, i.e., 
the local test execution checks if the test is executed locally and if so,
can we somehow tweak the operation so that the file in question is restored properly ???

It may not be much since |make mozmill| takes a long time anyway, but noticing the test seeming hung until the timeout kicks in is not quite pleasant. 
Yes, I watch the test log scroll by and the TB window redrawn while I do other things on my local PC,
and the long pause caused by this timeout while the dialog is shown is quite annoying :-)
[Actually, I can click the dialog to let the test proceed quickly, but I don't want to disturb the test by
unexpected manual intervention.]

TIa
this was done in Bug 876503, so the author of that may have a better idea/rationale for the folder deletion.  note that most of the remaining failures are in test-drafts.js, and the drafts folder is also removed (no idea if it's relevant to the drafts fails).
But if the folder is missing on disk, TB should recreate it automatically (by design). So we should not hack the test if there is a real bug in the core.
but relying on a completely unrelated test is the wrong way to discover such a bug. there should be a discrete test for folder creation on demand.
Blocks: 456053
(In reply to alta88 from comment #9)
> this is always the case, under linux, running locally. it is due to Outbox
> being removed by test-charset-upgrade.js teardownModule() and not being
> ready in time for the next test needing it; ie it works when those lines are
> removed.  by works, it means composition mozmill-one failures drop from 10
> to 9 and there's no disk space dialog.

Thanks, running only test-charset-upgrade.js and test-attachment-reminder locally finally reproduces the error for me.

We do not allow the user to delete Outbox from the UI, but in a test we do it. It seems we do not really re-create the folder automatically at all occasions. We create Outbox at account startup, but not always later on when it is suddenly missing (e.g. at Send later).

There is a dirty hack in e.g. nsMsgBrkMBoxStore::GetNewMsgOutputStream() to quickly create the backing file for the folder.

It adds to the confusion that the outbox folder is created on disk as "Unsent messages", while displayed as Outbox. In tests, we create it as Outbox on disk and in display. As long as the nsMsgFolderFlags.Queue is set on the folder properly, everything should work. If all code searches for the folder using the flag. But that is not true for some tests. In my current WIP patch, I got into a state where both Outbox and Unsent messages are created on disk, the first one is displayed in TB folder pane (as empty), while the latter has got the real queued message (via send later).
(In reply to :aceman from comment #14)
> (In reply to alta88 from comment #9)
> > this is always the case, under linux, running locally. it is due to Outbox
> > being removed by test-charset-upgrade.js teardownModule() and not being
> > ready in time for the next test needing it; ie it works when those lines are
> > removed.  by works, it means composition mozmill-one failures drop from 10
> > to 9 and there's no disk space dialog.
> 
> Thanks, running only test-charset-upgrade.js and test-attachment-reminder
> locally finally reproduces the error for me.
> 
> We do not allow the user to delete Outbox from the UI, but in a test we do
> it. It seems we do not really re-create the folder automatically at all
> occasions. We create Outbox at account startup, but not always later on when
> it is suddenly missing (e.g. at Send later).
> 

then why is it in the test?  you haven't said why the Outbox deletion was added in bug 876503, but it seems unlikely the intent was to test Outbox on demand. nor is it correct to say a folder should always be created on demand.

> There is a dirty hack in e.g. nsMsgBrkMBoxStore::GetNewMsgOutputStream() to
> quickly create the backing file for the folder.

yes, this is wrong. if a user went out of the way to delete Outbox, via file operation outside of Tb UI, it means they really don't want it in folderpane. or maybe an AV type thing deleted it. in both cases, the correct response is a dialog asking for creation of Outbox, and exiting Send Later if the user declines. the decision belongs much higher than GetNewMsgOutputStream. maybe the Copies and Folders panel should include Outbox, and take care that only it had the Queue flag, the folder with the flag is unique to the account, etc etc.

in the meantime, a green Z shouldn't be kept hostage to an Outbox audit, as the test action of deleting Outbox in the middle of a bunch of other inflight tests is bogus. pursuing why it didn't fail before seems an unproductive use of time, imo.
(In reply to alta88 from comment #15)
> then why is it in the test?  you haven't said why the Outbox deletion was
> added in bug 876503, but it seems unlikely the intent was to test Outbox on
> demand. nor is it correct to say a folder should always be created on demand.

I made a consolidation and when other folders like Drafts were created and deleted, then I thought that test was just missing the deletion of Outbox and I added it. Most tests using Outbox also create it beforehand.
Just that attachment-reminder does not.

> > There is a dirty hack in e.g. nsMsgBrkMBoxStore::GetNewMsgOutputStream() to
> > quickly create the backing file for the folder.
> 
> yes, this is wrong. if a user went out of the way to delete Outbox, via file
> operation outside of Tb UI, it means they really don't want it in
> folderpane.

I think we create it again automatically at TB startup. So the test is actually running an unsupported scenario of Outbox being removed (by code) while TB is running (which we do not allow the user to do via UI, but code can do it).

> or maybe an AV type thing deleted it. in both cases, the correct
> response is a dialog asking for creation of Outbox, and exiting Send Later
> if the user declines. the decision belongs much higher than
> GetNewMsgOutputStream. maybe the Copies and Folders panel should include
> Outbox, and take care that only it had the Queue flag, the folder with the
> flag is unique to the account, etc etc.

Yes, this would be a possibility for future work.

> in the meantime, a green Z shouldn't be kept hostage to an Outbox audit, as
> the test action of deleting Outbox in the middle of a bunch of other
> inflight tests is bogus. pursuing why it didn't fail before seems an
> unproductive use of time, imo.

Yes, that is what we can decide here now:
1. the easy quick fix is to remove the removal of the Outbox in the test.
2. in a followup bug I can continue to look into why the folder is not automatically created. There is some infrastructure to do it, but I'm not sure if it is working right.

Is the general consensus to only do 1. in this bug?
Looking at
https://hg.mozilla.org/comm-central/rev/46881f948e10
https://hg.mozilla.org/comm-central/rev/4805e92bc2cb
from bug 876503 I ask myself why drafts and outbox are deleted.

As Alta88 said, we should not do that but instead create a test that checks "just it time" creation of those folders.

I think there is consensus ;-)
Ok,alta would you like to make the quick patch now? You have found the problem. I can give you a review then.
Attached patch tests.patchSplinter Review
Attachment #8799715 - Flags: review?(acelists)
Comment on attachment 8799715 [details] [diff] [review]
tests.patch

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

I'm in favour of removing both Drafts and Outbox deletion as presented here.
Attachment #8799715 - Flags: review+
May I suggest a try push? ;)
I think you may ;-)
i don't have try, so if one of you could do it..
Keywords: checkin-needed
Do it again Sam, you pushed to a busted tree ;-)
May I suggest to change the commit message to:
Remove Drafts and Outbox deletion from test-charset-upgrade.js and test-drafts.js to fix crashes.
Comment on attachment 8799715 [details] [diff] [review]
tests.patch

Works for me, thanks. Please fix the commit message and add author.
Attachment #8799715 - Flags: review?(acelists) → review+
I did the fixes and landed it:
https://hg.mozilla.org/comm-central/rev/fb3474301afa6f1956aa663a4538b136ce65903e

Thanks for cooperation.
Assignee: acelists → alta88
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 52.0
One push later:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=9780f198b3bb4d1faffe528ba218fb1f3e207b58
a bunch of tests now fail on "Linux debug". Looks like we can't win here.
(In reply to Jorg K (GMT+2) from comment #30)
> One push later:
> https://treeherder.mozilla.org/#/jobs?repo=comm-
> central&revision=9780f198b3bb4d1faffe528ba218fb1f3e207b58
> a bunch of tests now fail on "Linux debug". Looks like we can't win here.

at least that's a different issue ;)
Comment on attachment 8799715 [details] [diff] [review]
tests.patch

[Approval Request Comment]
Regression caused by (bug #): previously hidden test bug
Testing completed (on c-c, etc.): fixes the test
Risk to taking this patch (and alternatives if risky): none

Not sure if beta needs this too
Attachment #8799715 - Flags: approval-comm-aurora?
Comment on attachment 8799715 [details] [diff] [review]
tests.patch

I'm not sure we're doing another TB 50 beta.
Attachment #8799715 - Flags: approval-comm-beta+
Attachment #8799715 - Flags: approval-comm-aurora?
Attachment #8799715 - Flags: approval-comm-aurora+
right, the bogus fail fixed here was especially bad as it hid a lot of other errors.
(In reply to alta88 from comment #34)
> right, the bogus fail fixed here was especially bad as it hid a lot of other
> errors.
So now that "bogus" is gone, can you fix the hidden error please ;-)
;D well that's not how "it" works..  not even necessarily if you've magically acquired a budget.
Blocks: 1310024
Hi all, I am on WIN 10, TB 52.2.1 (32-Bit) and getting this nasty bug since a week every day. Sometimes I even have to close that error-popup 50 times! This is the complete message from the error/debugging console: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIMsgMailNewsUrl.server]
I just found this thread and I guess it is related.
Could you please confirm, because this is driving me mad...
I will/can provide any help needed (which is in my possibilities).
Well, this bug here is fixed, in fact, it was fixed almost a year ago. Also, it was about a test failure.

So I guess you'll have to submit a new bug giving some details. Also, please try with add-ons disabled (see Help menu) first.
thanks, will do
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: