Intermittent mochitest-metro-chrome timeout after browser_test.js finishes in debug builds

RESOLVED WORKSFORME

Status

RESOLVED WORKSFORME
6 years ago
4 years ago

People

(Reporter: mbrubeck, Assigned: mbrubeck)

Tracking

({intermittent-failure})

Firefox Tracking Flags

(Not tracked)

Details

(Assignee)

Description

6 years ago
At least half the time when I run Metro browser-chrome tests in my debug build, I get a timeout after the last assertion in browser_test.js (which is the last test file) but before the "Shutdown" message.  It's as if browser_test.js had failed to finish(), but I don't see how that could happen.

TEST-START | chrome://mochitests/content/metro/browser_test.js
TEST-PASS | chrome://mochitests/content/metro/browser_test.js | continues on success
TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: 1357925738362	Sync.Tracker.Clients	WARN	Changed IDs file clients contains non-object value.

TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: 1357925738412	Sync.Tracker.Bookmarks	WARN	Changed IDs file bookmarks contains non-object value.

TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: 1357925738433	Sync.Tracker.Forms	WARN	Changed IDs file forms contains non-object value.

TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: 1357925738453	Sync.Tracker.History	WARN	Changed IDs file history contains non-object value.

TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: 1357925738471	Sync.Tracker.Passwords	WARN	Changed IDs file passwords contains non-object value.

TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: [JavaScript Warning: "ReferenceError: reference to undefined property message.level" {file: "resource://services-common/log4moz.js" line: 396}]
TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: 1357925738539	Sync.Tracker.Clients	WARN	Attempted to add undefined ID to tracker

TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: jssubloader/185/c:/users/mbrub_~1/appdata/local/temp/tmpi2vdn5/extensions/mochikit@mozilla.org/chrome/mochikit.jar/content/chrome-harness.js
TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: jssubloader/185/c:/Users/mbrub_000/src/elm/obj-debug/_tests/testing/mochitest/metro/head.js
TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: [JavaScript Error: "redeclaration of const COMPOSITION_ATTR_RAWINPUT" {file: "chrome://mochikit/content/tests/SimpleTest/EventUtils.js" line: 678}]
TEST-INFO | chrome://mochitests/content/metro/browser_test.js | Console message: jssubloader/185/c:/Users/mbrub_000/src/elm/obj-debug/_tests/testing/mochitest/metro/browser_test.js
TEST-PASS | chrome://mochitests/content/metro/browser_test.js | continues on failure
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/metro/browser_test.js | Test timed out
INFO TEST-END | chrome://mochitests/content/metro/browser_test.js | finished in 73242ms
TEST-INFO | checking window state

INFO TEST-START | Shutdown
Browser Chrome Test Summary
	Passed: 86
	Failed: 1
	Todo: 0

*** End BrowserChrome Test Results ***
(Assignee)

Comment 1

6 years ago
It seems like there's something wrong with our event loop in debug builds, or some other code is running really slowly and hogging the event loop for a long long time.  browser_test.js calls waitForAndContinue, which sets a 50-millisecond timeout.  Meanwhile, the test harness sets a 30-second timeout.  Neither of those timeouts is triggered until over 170 seconds later.

The reason the test fails is that even though it has called finish, the code to clear the timeout goes through Services.tm.mainThread.dispatch and doesn't get called in time:
http://hg.mozilla.org/mozilla-central/file/44dcffe8792b/testing/mochitest/browser-test.js#l572
(Assignee)

Comment 2

6 years ago
Disabling browser_remotetabs.js prevents the Sync stuff (see comment 0) from running, and allows the test to complete in 17 seconds instead of 170 seconds.  This is still dangerously close to the 30-second timeout threshold.
(Assignee)

Comment 3

6 years ago
In a non-debug build, everything works perfectly.  The 50ms timeout is called every 50ms as intended, and the whole tests completes in 2s as it should.  The only difference between the two builds is "--enable-debug".

Updated

6 years ago
Keywords: intermittent-failure
(Assignee)

Comment 4

6 years ago
I can't seem to reproduce this any more.  Maybe it was fixed by bug 817641 or by some other recent change.
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → WORKSFORME
OS: Windows 8 Metro → Windows 8.1
You need to log in before you can comment on or make changes to this bug.