819326 - Intermittent "command timed out: 5400 seconds elapsed, attempting to kill" during mochitest-bc tests on Windows debug builds

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Ed Morley [:emorley]]

Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound debug test mochitest-browser-chrome on 2012-12-05 05:57:58 PST for push aa649086ab5b

slave: talos-r4-snow-030

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

{
TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.js | Console message: LOG addons.updates: Found an update entry for [e-mail] version 2.0
TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.js | Console message: LOG addons.updates: Requesting https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x2 0x5001 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b0005 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b000a https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b0006 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x2 0x5003 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x2 0x5004 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b0005 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b000a https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** Received redirect for http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b0006 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b0006 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x2 0x5005 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x2 0x5006 https://example.com/browser/toolkit/mozapps/extensions/test/browser/redirect.sjs?http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x2 0x5001 http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b0005 http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf
*** HTTP Activity 0x1 0x804b000a http://example.com/browser/toolkit/mozapps/extensions/test/browser/browser_updatessl.rdf

command timed out: 5400 seconds elapsed, attempting to kill
}

Comment 1

[(no longer active)]

This is just the test taking more than 90 minutes, and is not related to a particular test.  Ted, do you know where this value is set?  Our windows browser-chrome test can now take between 95-100 minutes.

Comment 2

[(no longer active)]

python mochitest/runtests.py --appname=./FirefoxNightlyDebug.app/Contents/MacOS/firefox-bin --utility-path=bin --extra-profile-file=bin/plugins --certificate-path=certs --autorun --close-when-done --console-level=INFO --symbols-path=http://ftp-scl3.mozilla.com/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-macosx64-debug/1354714755/firefox-20.0a1.en-US.mac64.crashreporter-symbols.zip --browser-chrome
 in dir /Users/cltbld/talos-slave/test/build (timeout 1200 secs) (maxTime 5400 secs)


This seems to be set on the buildbot.  Moving to releng.

Comment 4

[(no longer active)]

This blocks bug 818732, since the tests for per-window private browsing open a number of new windows and they regularly take between 95-100 minutes on Windows debug builds.

I was planning on fixing bug 818732 tomorrow, so I'd really appreciate if you can bump this timeout on buildbot some time tomorrow.  Thanks!

(See the Birch branch if you want to get a sense of the usual runtimes of this mochitest-bc on Windows.)

Comment 5

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17759380&tree=Birch
Rev3 WINNT 5.1 birch debug test mochitest-browser-chrome on 2012-12-09 02:12:54
slave: talos-r3-xp-085

command timed out: 5400 seconds elapsed, attempting to kill

Comment 6

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17759362&tree=Birch
Rev3 WINNT 6.1 birch debug test mochitest-browser-chrome on 2012-12-09 02:12:40
slave: talos-r3-w7-014

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_cmd_calllog.js | Test timed out
command timed out: 5400 seconds elapsed, attempting to kill

Comment 7

[Nick Thomas [:nthomas] (UTC+12)]

Attachment: [buildbotcustom] Global bump to 2hrs

Since we don't have anything finer grained, this bumps the maxTime to 2 hours for all mochitest jobs (all test types, opt & debug).

Comment 8

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17765462&tree=Birch
Rev3 WINNT 5.1 birch debug test mochitest-browser-chrome on 2012-12-09 12:13:21
slave: talos-r3-xp-080

command timed out: 5400 seconds elapsed, attempting to kill

Comment 9

[(no longer active)]

Note that there is also a bug somewhere in buildbot which prevents it from actually killing the job, so the test runs to completion.  But I'm not really interested in that but getting fixed here.  ;-)

Comment 10

[Nick Thomas [:nthomas] (UTC+12)]

Bug 798170 should have fixed that, so you coop is probably sad/raging now.

Comment 11

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17769929&tree=Birch
Rev3 WINNT 5.1 birch debug test mochitest-browser-chrome on 2012-12-09 19:30:45
slave: talos-r3-xp-072

command timed out: 5400 seconds elapsed, attempting to kill

Comment 12

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17769928&tree=Birch
Rev3 WINNT 6.1 birch debug test mochitest-browser-chrome on 2012-12-09 19:30:34
slave: talos-r3-w7-061

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_cmd_calllog.js | Test timed out
command timed out: 5400 seconds elapsed, attempting to kill

Comment 13

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17773992&tree=Birch
Rev3 WINNT 5.1 birch debug test mochitest-browser-chrome on 2012-12-10 01:43:05
slave: talos-r3-xp-096

command timed out: 5400 seconds elapsed, attempting to kill

Comment 14

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17773901&tree=Birch
Rev3 WINNT 6.1 birch debug test mochitest-browser-chrome on 2012-12-10 01:43:11
slave: talos-r3-w7-081

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_cmd_calllog_chrome.js | Test timed out
command timed out: 5400 seconds elapsed, attempting to kill
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 3979627 bytes during test execution
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 2 instances of AsyncStatement with size 48 bytes each (96 bytes total)
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 2097 instances of AtomImpl with size 24 bytes each (50328 bytes total)
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 1 instance of BackstagePass with size 24 bytes
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 1 instance of BodyRule with size 16 bytes
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 1 instance of CalculateFrecencyFunction with size 12 bytes

Comment 15

[John Hopkins (:jhopkins)]

Comment on attachment 690225 [details] [diff] [review]
[buildbotcustom] Global bump to 2hrs

Landed in http://hg.mozilla.org/build/buildbotcustom/rev/921c53f61fe4

Comment 16

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17785724&tree=Birch
Rev3 WINNT 5.1 birch debug test mochitest-browser-chrome on 2012-12-10 08:50:35
slave: talos-r3-xp-066

command timed out: 5400 seconds elapsed, attempting to kill

Comment 17

[Legacy TBPL/Treeherder Robot]

ehsan
https://tbpl.mozilla.org/php/getParsedLog.php?id=17782678&tree=Birch
Rev3 WINNT 5.1 birch debug test mochitest-browser-chrome on 2012-12-10 07:15:46
slave: talos-r3-xp-052

command timed out: 5400 seconds elapsed, attempting to kill

Comment 18

[[e-mail] (:bhearsum)]

In production

Comment 19

[(no longer active)]

This seems to be fixed now, thanks!