Closed Bug 824022 Opened 12 years ago Closed 11 years ago

Intermittent test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js, test_dictionary.js, test_theme.js | Test timed out

Categories

(Toolkit :: Add-ons Manager, defect)

Product:
Toolkit
Component:
Add-ons Manager
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME
Milestone:
mozilla22

People

(Reporter: emorley, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

timeout patch
2.37 KB, patch
Unfocused
: review+
Details | Diff | Splinter Review 
Rev3 WINNT 5.1 mozilla-inbound opt test xpcshell on 2012-12-19 22:00:02 PST for push e48db20a0a46

slave: talos-r3-xp-022

https://tbpl.mozilla.org/php/getParsedLog.php?id=18119712&tree=Mozilla-Inbound

{
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_gfxBlacklist_prefs.js | running test ...
TEST-PASS | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_gfxBlacklist_prefs.js | test passed (time: 266.000ms)
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_hasbinarycomponents.js | running test ...
TEST-PASS | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_hasbinarycomponents.js | test passed (time: 1953.000ms)
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_hotfix.js | running test ...
TEST-PASS | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_hotfix.js | test passed (time: 9312.000ms)
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell-unpack\test_install.js | running test ...

command timed out: 1200 seconds without output, attempting to kill
}
Rev3 WINNT 5.1 mozilla-inbound opt test xpcshell on 2012-12-20 00:30:21 PST for push bb90ec82052b

slave: talos-r3-xp-009

https://tbpl.mozilla.org/php/getParsedLog.php?id=18122609&tree=Mozilla-Inbound

{
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_LightweightThemeManager.js | running test ...
TEST-PASS | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_LightweightThemeManager.js | test passed (time: 1031.000ms)
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_backgroundupdate.js | running test ...
TEST-PASS | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_backgroundupdate.js | test passed (time: 1656.000ms)
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_badschema.js | running test ...
TEST-PASS | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_badschema.js | test passed (time: 3719.000ms)
TEST-INFO | c:\talos-slave\test\build\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_blocklistchange.js | running test ...

command timed out: 1200 seconds without output, attempting to kill
}
Summary: Intermittent Windows "command timed out: 1200 seconds without output, attempting to kill" during mozapps\extensions\test\xpcshell-unpack\test_install.js → Intermittent Windows "command timed out: 1200 seconds without output, attempting to kill" during mozapps\extensions\test\xpcshell-unpack\test_install.js, test_blocklistchange.js
Add-ons Manager is the component for mozapps\extensions\
Component: Application Update → Add-ons Manager
https://tbpl.mozilla.org/php/getParsedLog.php?id=18171562&tree=Mozilla-Inbound
Summary: Intermittent Windows "command timed out: 1200 seconds without output, attempting to kill" during mozapps\extensions\test\xpcshell-unpack\test_install.js, test_blocklistchange.js → Intermittent Windows "command timed out: 1200 seconds without output, attempting to kill" during mozapps\extensions\test\xpcshell-unpack\test_install.js, test_blocklistchange.js, test_bootstrap.js
Summary: Intermittent Windows "command timed out: 1200 seconds without output, attempting to kill" during mozapps\extensions\test\xpcshell-unpack\test_install.js, test_blocklistchange.js, test_bootstrap.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js, test_install.js
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js, test_install.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js, test_install.js, test_update.js
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js, test_install.js, test_update.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js, test_install.js, test_update.js, test_filepointer.js
Dave, don't suppose you could take a look at this? :-)
Flags: needinfo?(dtownsend+bugmail)
(In reply to Ed Morley [UTC+0; email:edmorley@moco] from comment #25)
> Dave, don't suppose you could take a look at this? :-)

Is there any way to get more detailed logging for xpcshell tests? I recall it used to log what checks were running making it possible to at least see where in the files it was failing but that doesn't seem to be in the logs anymore. Without that I don't know how I could figure this out.
Flags: needinfo?(dtownsend+bugmail)
Ted, could you advise as to how to enable more logging for xpcshell (comment 31)? Thanks :-)
Flags: needinfo?(ted)
There's no straightforward way to do this right now. The xpcshell harness suppresses xpcshell's output (and thus the test's output) unless it sees the test fail. Since the harness doesn't handle timeouts (bug 597064), you won't get to see the output on a timeout. There is a --verbose option that causes the harness to make all the output visible: http://mxr.mozilla.org/mozilla-central/source/testing/xpcshell/runxpcshelltests.py#1019, we use that for check-one and check-interactive. We could flip the default there to be verbose for a bit on Tinderbox, but it's going to bloat the logs quite a bit.

Alternately, with a little bit of work we could add a "verbose = true" annotation to the manifest to toggle on verbose mode for individual tests/groups of tests.
Flags: needinfo?(ted)
I have added timeout checks to most of the app update tests due to this and other reasons and force the test to fail for just this reason. It should be possible to do that for these tests as well.
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_install.js, test_blocklistchange.js, test_bootstrap.js, test_install_strictcompat.js, test_install.js, test_update.js, test_filepointer.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js, test_dictionary.js
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js, test_dictionary.js → Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js, test_dictionary.js, test_theme.js
Attached patch timeout patch — — Splinter Review 
This forces any add-ons manager xpcshell test that runs for longer than 15 minutes to long an error and exit. If we're ever actually hitting that length for a single test then something is wrong and this is shorter than the 20 minute timeout that buildbot kicks in.
Attachment #717379 - Flags: review?(bmcbride)
Comment on attachment 717379 [details] [diff] [review]
timeout patch

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

Wish there was a way to get a useful stack trace when this happens :(

::: toolkit/mozapps/extensions/test/xpcshell/head_addons.js
@@ +13,5 @@
>  const PREF_EM_MIN_COMPAT_APP_VERSION      = "extensions.minCompatibleAppVersion";
>  const PREF_EM_MIN_COMPAT_PLATFORM_VERSION = "extensions.minCompatiblePlatformVersion";
>  
> +// Forcibly end the test if it runs longer than 15 minutes
> +const TIMEOUT = 900000;

Nit: TIMEOUT_MS ?
Attachment #717379 - Flags: review?(bmcbride) → review+
(In reply to Blair McBride [:Unfocused] (Back from the dead. Mostly.) from comment #213)
> Comment on attachment 717379 [details] [diff] [review]
> timeout patch
> 
> Review of attachment 717379 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Wish there was a way to get a useful stack trace when this happens :(

At least this will tell us where in the tests the failure happens and hopefully a JS exception of some kind getting logged.

https://hg.mozilla.org/integration/mozilla-inbound/rev/433b78064bfb

Note that this will change the error logged to "Test ran longer than 900000ms"
https://hg.mozilla.org/mozilla-central/rev/433b78064bfb
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla22
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Whiteboard: [leave open]
Ok, the timeout patch landed, I verified it worked locally with a short timeout and yet we still see buildbot timeouts. That doesn't make a lot of sense to me.
I don't really pay much attention to these, but it feels like the distribution might have changed from "any damn addon test" to "test_bootstrap.js."
Dave, do you have any more ideas for this? This is still one of our top failures on OrangeFactor. Thank you :-)
Flags: needinfo?(dtownsend+bugmail)
(In reply to Ed Morley [:edmorley UTC+0] from comment #283)
> Dave, do you have any more ideas for this? This is still one of our top
> failures on OrangeFactor. Thank you :-)

Until I can find a way to get a log I really don't have anything to go on. I don't understand why the patch didn't cause the tests to fail cleanly unless the xpcshell process has completely hung. I looked into being able to switch on verbose mode for these tests but that wouldn't actually help as even then the log is only outputted after the xpcshell process exits and buildbot is killing things sooner than that. I think the only option is to get bug 597064 fixed.
Depends on: 597064
Flags: needinfo?(dtownsend+bugmail)
Could you take another look at this? :-)
Flags: needinfo?(dtownsend+bugmail)
(In reply to Ed Morley [:edmorley UTC+0] from comment #369)
> Could you take another look at this? :-)

As I said in comment 300, there really isn't anything I can do until I can get a log, can we get the priority of bug 597064 increased?
Flags: needinfo?(dtownsend+bugmail)
(In reply to Dave Townsend (:Mossop) from comment #374)
> (In reply to Ed Morley [:edmorley UTC+0] from comment #369)
> > Could you take another look at this? :-)
> 
> As I said in comment 300, there really isn't anything I can do until I can
> get a log, can we get the priority of bug 597064 increased?

Sorry, so many comments, missed/forgot about that one.
Doesn't look like bug 859065 is giving us any better information on this one :(
So does the log information from comment 944, now that we time it out and dump the log, help?
Flags: needinfo?(dtownsend+bugmail)
(In reply to Phil Ringnalda (:philor) from comment #945)
> So does the log information from comment 944, now that we time it out and
> dump the log, help?

The log tells me that the test actually completed successfully, xpcshell even ran the cleanup functions and logged the fact that all checks in the test passed, i.e. it makes it to the end of the main _execute_test function in the xpcshell test harness (http://mxr.mozilla.org/mozilla-central/source/testing/xpcshell/head.js#386). Then apparently it just fails to exit the xpcshell process, so the question becomes what would cause that to happen?
Flags: needinfo?(dtownsend+bugmail)
"Windows."

Is that a time when we would be likely to try to delete a file? Windows hates when we try to delete files, almost as much as it hates it when we don't delete files.
No longer blocks: 856027
Depends on: 874647
Dave, don't suppose you could take another look at this? I know it's a bit of a nuisance failure, but I'd really like to avoid disabling swathes of these tests if possible. Cheers! :-)
Flags: needinfo?(dtownsend+bugmail)
Depends on: 877297
(In reply to Ed Morley [:edmorley UTC+1] from comment #1235)
> Dave, don't suppose you could take another look at this? I know it's a bit
> of a nuisance failure, but I'd really like to avoid disabling swathes of
> these tests if possible. Cheers! :-)

I'm trying the tack of getting a build slave to see if I can reproduce this there. If I can't I don't know what else I can do, this seems to be a bug in xpcshell since we should be calling quit(0) and it isn't. I might be able to debug into why it doesn't quit if I can reproduce it.
Flags: needinfo?(dtownsend+bugmail)
Blocks: 854330
Summary: Intermittent "command timed out: 1200 seconds without output, attempting to kill" during test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js, test_dictionary.js, test_theme.js → Intermittent test_blocklistchange.js, test_bootstrap.js, test_install[_strictcompat].js, test_update[_strictcompat].js, test_filepointer.js, test_dictionary.js, test_theme.js | Test timed out
This went away after bug 883657 landed.
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → WORKSFORME
Whiteboard: [leave open]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: