465490 - Intermittent time out after test_0051_general.js: test_0110_general.js hangs randomly

Status: RESOLVED FIXED

(Toolkit :: Application Update, defect)

Description

[Robert O'Callahan (:roc) (email my personal email if necessary)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1226993816.1226998643.13195.gz#err0

Looks like the first test to not pass was test_0110_general.js

Comment 1

[Serge Gautherie (:sgautherie)]

{
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229823522.1229828011.5217.gz
MacOSX Darwin 9.2.2 mozilla-central moz2-darwin8-slave01 dep unit test on 2008/12/20 17:38:42

TEST-PASS | ../../../../_tests/xpcshell-simple/test_update/unit/test_0051_general.js | all tests passed
command timed out: 300 seconds without output, killing pid 36438
}

Comment 2

[Robert Strong (they/them - no direct email)]

No idea why this would be happening about once a month on only one Mac OS X systems... any insights from anyone as to why?

Comment 3

[Serge Gautherie (:sgautherie)]

(In reply to comment #0)
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1226993816.1226998643.13195.gz#err0

MacOSX Darwin 9.2.2 moz2-darwin8-slave02 dep unit test on 2008/11/17 23:36:56


(In reply to comment #2)
> No idea why this would be happening about once a month on only one Mac OS X

What ? It certainly happens (much) more often than that !

Trunk:
{
...

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229496465.1229500933.10651.gz
MacOSX Darwin 9.2.2 mozilla-central moz2-darwin8-slave01 dep unit test on 2008/12/16 22:47:45

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229506509.1229512041.8331.gz
MacOSX Darwin 9.2.2 mozilla-central moz2-darwin8-slave01 dep unit test on 2008/12/17 01:35:09

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1229737744.1229743825.20293.gz
MacOSX Darwin 9.2.2 mozilla-central moz2-darwin8-slave01 dep unit test on 2008/12/19 17:49:04
}

1.9.1 Branch
{
...

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1229632834.1229637645.11362.gz
MacOSX 10.5.2 mozilla-1.9.1 moz2-darwin9-slave05 dep unit test on 2008/12/18 12:40:34

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1229654434.1229659226.31228.gz
MacOSX 10.5.2 mozilla-1.9.1 moz2-darwin9-slave05 dep unit test on 2008/12/18 18:40:34

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1229665234.1229670216.27288.gz
MacOSX 10.5.2 mozilla-1.9.1 moz2-darwin9-slave05 dep unit test on 2008/12/18 21:40:34

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1229691982.1229696798.14879.gz
MacOSX 10.5.2 mozilla-1.9.1 moz2-darwin9-slave05 dep unit test on 2008/12/19 05:06:22

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1229719234.1229724080.2091.gz
MacOSX 10.5.2 mozilla-1.9.1 moz2-darwin9-slave05 dep unit test on 2008/12/19 12:40:34

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1229827234.1229831999.12598.gz
MacOSX 10.5.2 mozilla-1.9.1 moz2-darwin9-slave05 dep unit test on 2008/12/20 18:40:34
}

> systems... any insights from anyone as to why?

Now, why "only" (as it would seem) these 2(-3) MacOSX slaves.?. I don't know.

Comment 4

[Robert Strong (they/them - no direct email)]

I thought your comment #1 was to say it had just happened again and I hadn't seen the other occurrences though I look at the logs often... thanks for the heads up!

Comment 5

[Robert Strong (they/them - no direct email)]

So, the updater code for Mac OS X sleeps for 5 seconds iirc. It may be possible to fix this by making this two tests instead of one.

Comment 6

[Robert Strong (they/them - no direct email)]

Attachment: possible patch rev1

Hey Dave, I think the problem with this test on Mac OS X may be due to calling the updater binary twice in the same test and perhaps the following
http://mxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/src/updater/progressui_osx.mm#126

Comment 7

[Dave Townsend [:mossop]]

(In reply to comment #6)
> Created an attachment (id=355348) [details]
> possible patch rev1
> 
> Hey Dave, I think the problem with this test on Mac OS X may be due to calling
> the updater binary twice in the same test and perhaps the following
> http://mxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/src/updater/progressui_osx.mm#126

I'm not sure I see how splitting out the latter part of the test into its own unit test file will help, or have I missed something?

Comment 8

[Robert Strong (they/them - no direct email)]

(In reply to comment #7)
> (In reply to comment #6)
> > Created an attachment (id=355348) [details] [details]
> > possible patch rev1
> > 
> > Hey Dave, I think the problem with this test on Mac OS X may be due to calling
> > the updater binary twice in the same test and perhaps the following
> > http://mxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/src/updater/progressui_osx.mm#126
> 
> I'm not sure I see how splitting out the latter part of the test into its own
> unit test file will help, or have I missed something?
The systems where the test fails are all Mac OS X and the only significant difference I know of is the usleep(500000) call. I'm not by any means positive this will fix it but I do suspect that it is caused at least in part by the usleep(500000) call. Perhaps also sleeping for 5 seconds in the script might help as well... I'll take another look later.

Comment 9

[Dave Townsend [:mossop]]

Comment on attachment 355348 [details] [diff] [review]
possible patch rev1

If splitting it out helps then it's ok by me

Comment 10

[Robert Strong (they/them - no direct email)]

Attachment: test cleanup

I'm going to hold off on trying out the first patch for now and instead cleanup the test so it only tests the updater binary application of a mar file.

Comment 11

[Robert Strong (they/them - no direct email)]

Comment on attachment 371581 [details] [diff] [review]
test cleanup

btw: some cruft from test_0010_general.js snuck in here

Comment 12

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1239139996.1239144966.4444.gz
OS X 10.5.2 mozilla-1.9.1 unit test on 2009/04/07 14:33:16

Passed with 'check' then timed out with new 'xpcshell-tests' ;->

Comment 13

[Robert Strong (they/them - no direct email)]

Attachment: patch - separation of tests, cleanup, and logging

Comment 14

[Robert Strong (they/them - no direct email)]

Attachment: patch - separation of tests, cleanup, and additional logging (checked in)

I'll land this on mozilla-central after the tree is greener

Comment 15

[Robert Strong (they/them - no direct email)]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/b88debed88e0

Comment 16

[Robert Strong (they/them - no direct email)]

Comment on attachment 371945 [details] [diff] [review]
patch - separation of tests, cleanup, and additional logging (checked in)

Also pushed to mozilla-central
http://hg.mozilla.org/mozilla-central/rev/9213aa676ae6

If anyone sees another one of these failures please comment in the bug so I can take a look at the logs. Thanks

Comment 17

[Robert Strong (they/them - no direct email)]

Attachment: patch - followup removal of unused test data files

Comment 18

[Shawn Wilsher :sdwilsh]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1239650285.1239655356.662.gz&fulltext=1#err0

Testing: successful removal of the directory used to apply the mar file
Testing: cleanup of the updates directory used to test
Testing: updater binary process exitValue for success when applying a complete mar
Testing: contents of files added by a complete mar
Unable to remove directory
path: /builds/moz2_slave/mozilla-1.9.1-macosx-unittest/build/objdir/_tests/xpcshell/test_update/unit/app_dir/updates/0
Exception: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsILocalFile.remove]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: /builds/moz2_slave/mozilla-1.9.1-macosx-unittest/build/objdir/_tests/xpcshell/test_update/unit/test_0110_general.js :: run_test :: line 113"  data: no]
Testing: successful removal of the updates subdirectory where the updater binary was launched

Comment 19

[Robert Strong (they/them - no direct email)]

Looks like the additional logging tracked down where this was failing... I'll have a patch shortly. Thanks sdwilsh!

Comment 20

[Robert Strong (they/them - no direct email)]

Attachment: patch (checked in)

I believe this should fix this bug once and for all.

Comment 21

[Serge Gautherie (:sgautherie)]

(In reply to comment #18)

This looks like bug 473385, no?

Comment 22

[Robert Strong (they/them - no direct email)]

Could very well be. The patch as it stands should be sufficient to prevent this bug from happening in the future.

Comment 23

[Robert Strong (they/them - no direct email)]

btw: for this bug the failure could very well be due to the binary being launched prior to the directory being removed especially since the only failures have been with this test and the latest failure also points to this being the cause. So, I'm not convinced this has anything to do with bug 473385.

Comment 24

[Robert Strong (they/them - no direct email)]

Comment on attachment 372472 [details] [diff] [review]
patch (checked in)

Pushed to mozilla-central
http://hg.mozilla.org/mozilla-central/rev/79c0e45ad285

Pushed to mozilla-1.9.1
http://hg.mozilla.org/releases/mozilla-1.9.1/rev/8bc65d6e998e

Comment 25

[Robert Strong (they/them - no direct email)]

If anyone sees another one of these failures please reopen this bug so I can
investigate further. Thanks