Closed Bug 824022 Opened 8 years ago Closed 7 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)

x86
Windows XP
defect
Not set
normal

Tracking

()

RESOLVED WORKSFORME
mozilla22

People

(Reporter: emorley, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

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 patchSplinter 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: 8 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)