Closed Bug 965677 Opened 11 years ago Closed 10 years ago

Intermittent B2G mochitest timeouts showing only "Return code: 247" in the summary

Categories

(Firefox OS Graveyard :: General, defect)

Product:
Firefox OS Graveyard
Component:
General
Platform:
All
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: KWierso, Unassigned)

References

Details

I've filed several of these today that I'll dupe over to here instead of filing one for each instance of this happening.
I'm retriggering back to early this morning to see if I can find where these started failing so horribly.
Summary: Intermittent B2G mochitest-1 tests crashing with application timed out after 330 seconds with no output | application crashed [@ libc-2.15.so + 0xe8403] → Intermittent B2G tests crashing with application timed out after 330 seconds with no output | application crashed [@ libc-2.15.so + 0xe8403]
The 'crash' is just the harness forcing a crash since the process has hung, in order to get a stack.
Summary: Intermittent B2G tests crashing with application timed out after 330 seconds with no output | application crashed [@ libc-2.15.so + 0xe8403] → Intermittent B2G tests hanging with application timed out after 330 seconds with no output | application crashed [@ libc-2.15.so + 0xe8403]
Summary: Intermittent B2G tests hanging with application timed out after 330 seconds with no output | application crashed [@ libc-2.15.so + 0xe8403] → Intermittent B2G test timeouts with "Exception marionette.errors.InvalidResponseException: InvalidResponseException()" present in the log
Many of the timeouts are accompanied by this exception:
"Exception marionette.errors.InvalidResponseException: InvalidResponseException()"

eg:

{
06:56:40     INFO -  1391093746655	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":"3-b2g","name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[true,"http://mochi.test:8888/tests/?autorun=1&closeWhenDone=1&logFile=%2Fdata%2Flocal%2Ftests%2Flog%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&totalChunks=15&thisChunk=15&hideResultsTable=1&testManifest=b2g-debug.json&runOnly=false&dumpOutputDirectory=%2Ftmp"],"filename":"remote.py","script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, v. 2.0. If a copy of the MPL was not distributed with this\n * file, You can obtain one at http://mozilla.org/MPL/2.0/. */\n\nlet outOfProcess = __marionetteParams[0]\nlet mochitestUrl = __marionetteParams[1]\n\nconst CHILD_SCRIPT = \"chrome://specialpowers/content/specialpowers.js\";\nconst CHILD_SCRIPT_API = \"chrome://specialpowers/content/specialpowersAPI.js\";\nconst CHILD_LOGGER_SCRIPT = \"chrome://specialpowers/content/MozillaLogger.js\";\n\nlet homescreen = document.getElementById('systemapp');\nlet container = homescreen.contentWindow.document.getElementById('test-container');\n\nfunction openWindow(aEvent) {\n  var popupIframe = aEvent.detail.frameElement;\n  popupIframe.setAttribute('style', 'position: absolute; left: 0; top: 0px; background: white;');\n\n  // This is to size the iframe to what is requested in the window.open call,\n  // e.g. window.open(\"\", \"\", \"width=600,height=600\");\n  if (aEvent.detail.features.indexOf('width') != -1) {\n    let width = aEvent.detail.features.substr(aEvent.detail.features.indexOf('width')+6);\n    width = width.substr(0,width.indexOf(',') == -1 ? width.length : width.indexOf(','));\n    popupIframe.style.width = width + 'px';\n  }\n  if (aEvent.detail.features.indexOf('height') != -1) {\n    let height = aEvent.detail.features.substr(aEvent.detail.features.indexOf('height')+7);\n    height = height.substr(0, height.indexOf(',') == -1 ? height.length : height.indexOf(','));\n    popupIframe.style.height = height + 'px';\n  }\n\n  popupIframe.addEventListener('mozbrowserclose', function(e) {\n    container.parentNode.removeChild(popupIframe);\n    container.focus();\n  });\n\n  // yes, the popup can call window.open too!\n  popupIframe.addEventListener('mozbrowseropenwindow', openWindow);\n\n  popupIframe.addEventListener('mozbrowserloadstart', function(e) {\n    popupIframe.focus();\n    let mm = popupIframe.QueryInterface(Ci.nsIFrameLoaderOwner).frameLoader.messageManager;\n    mm.loadFrameScript(CHILD_LOGGER_SCRIPT, true);\n    mm.loadFrameScript(CHILD_SCRIPT_API, true);\n    mm.loadFrameScript(CHILD_SCRIPT, true);\n    mm.loadFrameScript('data:,attachSpecialPowersToWindow%28content%29%3B', true);\n  });\n\n  container.parentNode.appendChild(popupIframe);\n}\ncontainer.addEventListener('mozbrowseropenwindow', openWindow);\n\nif (outOfProcess) {\n  let specialpowers = {};\n  let loader = Cc[\"@mozilla.org/moz/jssubscript-loader;1\"].getService(Ci.mozIJSSubScriptLoader);\n  loader.loadSubScript(\"chrome://specialpowers/content/SpecialPowersObserver.js\", specialpowers);\n  let specialPowersObserver = new specialpowers.SpecialPowersObserver();\n\n  let mm = container.QueryInterface(Ci.nsIFrameLoaderOwner).frameLoader.messageManager;\n  specialPowersObserver.init(mm);\n\n  mm.addMessageListener(\"SPPrefService\", specialPowersObserver);\n  mm.addMessageListener(\"SPProcessCrashService\", specialPowersObserver);\n  mm.addMessageListener(\"SPPingService\", specialPowersObserver);\n  mm.addMessageListener(\"SpecialPowers.Quit\", specialPowersObserver);\n  mm.addMessageListener(\"SpecialPowers.Focus\", specialPowersObserver);\n  mm.addMessageListener(\"SPPermissionManager\", specialPowersObserver);\n  mm.addMessageListener(\"SPLoadChromeScript\", specialPowersObserver);\n  mm.addMessageListener(\"SPChromeScriptMessage\", specialPowersObserver);\n\n  mm.loadFrameScript(CHILD_LOGGER_SCRIPT, true);\n  mm.loadFrameScript(CHILD_SCRIPT_API, true);\n  mm.loadFrameScript(CHILD_SCRIPT, true);\n  //Workaround for bug 848411, once that bug is fixed, the following line can be removed\n  mm.loadFrameScript('data:,addEventListener%28%22DOMWindowCreated%22%2C%20function%28e%29%20%7B%0A%20%20removeEventListener%28%22DOMWindowCreated%22%2C%20arguments.callee%2C%20false%29%3B%0A%20%20var%20window%20%3D%20e.target.defaultView%3B%0A%20%20window.wrappedJSObject.SpecialPowers.addPermission%28%22allowXULXBL%22%2C%20true%2C%20window.document%29%3B%0A%7D%0A%29%3B', true);\n\n  specialPowersObserver._isFrameScriptLoaded = true;\n}\n\ncontainer.src = mochitestUrl;\n","line":178}}, id: {a75ed81d-e236-4028-af37-5a4fd7e5ee31}
06:56:40     INFO -  1391093748248	Marionette	INFO	sendToClient: {"from":"0","value":null}, {a75ed81d-e236-4028-af37-5a4fd7e5ee31}, {a75ed81d-e236-4028-af37-5a4fd7e5ee31}
06:56:40     INFO -  [Child 744] WARNING: NS_ENSURE_TRUE(lowMemFd != -1) failed: file ../../../gecko/widget/gonk/GonkMemoryPressureMonitoring.cpp, line 130
06:56:40     INFO -  [Child 744] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file ../../../gecko/toolkit/xre/nsXREDirProvider.cpp, line 1324
06:56:40     INFO -  [Child 744] WARNING: nsWindow::GetNativeData not implemented for this type: file ../../../gecko/widget/xpwidgets/PuppetWidget.cpp, line 717
06:56:40     INFO -  ###################################### forms.js loaded
06:56:40     INFO -  ############################### browserElementPanning.js loaded
06:56:40     INFO -  ######################## BrowserElementChildPreload.js loaded
06:56:40     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
06:56:40     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
06:56:40     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
06:56:40     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
07:04:21     INFO -  [Parent B2GRunner TEST-UNEXPECTED-FAIL | automation | application timed out after 450.0 seconds with no output
07:04:22     INFO -  B2GRunner INFO | checking for crashes in '/data/local/tests/profile/minidumps'
07:05:31     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: end.
07:05:33     INFO -  687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
07:05:33     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
07:05:33     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
07:05:33     INFO -  [Child 744] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../gecko/dom/xbl/nsXBLDocumentInfo.cpp, line 451
07:05:33     INFO -  [Child 744] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../gecko/dom/xbl/nsXBLDocumentInfo.cpp, line 521
07:05:33     INFO -  [Child 744] WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file ../../../gecko/docshell/base/nsDocShell.cpp, line 8521
07:05:33     INFO -  [Child 744] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file ../../../../../gecko/content/html/document/src/nsHTMLContentSink.cpp, line 717
07:05:33     INFO -  [Parent 687] ###!!! ASSERTION: Should be on main thread.: 'NS_IsMainThread()', file ../../../gecko/gfx/layers/ipc/ShadowLayerUtilsGralloc.cpp, line 259
07:05:33     INFO -  [Parent 687] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file ../../../../gecko/netwerk/base/src/nsSocketTransport2.h, line 195
07:05:33     INFO -  Exception marionette.errors.InvalidResponseException: InvalidResponseException() in <bound method Marionette.__del__ of <marionette.marionette.Marionette object at 0x2065390>> ignored
07:05:33    ERROR - Return code: 247
}

{
06:21:18     INFO -  5210 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_email.html | Element should not suffer from type mismatch (with value='foo@foo.barQ')
06:21:18     INFO -  5211 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_email.html | Element should be valid
06:26:48     INFO -  5212B2GRunner TEST-UNEXPECTED-FAIL | /tests/content/html/content/test/forms/test_input_email.html | application timed out after 330.0 seconds with no output
06:26:49     INFO -  B2GRunner INFO | checking for crashes in '/data/local/tests/profile/minidumps'
06:27:58     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: end.
06:28:08     INFO -   INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_email.html | Element should be valid
06:28:08     INFO -  5213 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_email.html | The invalid event should not have been thrown
06:28:08     INFO -  5214 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_email.html | Validation message should be the empty string
06:28:08     INFO -  5215 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_email.html | :valid pseudo-class should apply
06:28:08     INFO -  Exception marionette.errors.InvalidResponseException: InvalidResponseException() in <bound method Marionette.__del__ of <marionette.marionette.Marionette object at 0x1f7e3d0>> ignored
06:28:08    ERROR - Return code: 247
}
Summary: Intermittent B2G test timeouts with "Exception marionette.errors.InvalidResponseException: InvalidResponseException()" present in the log → Intermittent B2G test timeouts with "Exception marionette.errors.InvalidResponseException: InvalidResponseException()" present in the log ("Return code: 247")
Depends on: 965782
Failures still occurring even though bug 965782 is fixed; must have been unrelated, yey.
Summary: Intermittent B2G test timeouts with "Exception marionette.errors.InvalidResponseException: InvalidResponseException()" present in the log ("Return code: 247") → Intermittent B2G mochitest timeouts ("Return code: 247")
So much orange... Do we have a regression range here?
(In reply to Gregor Wagner [:gwagner] from comment #236)
> So much orange... Do we have a regression range here?

Not really. These have been getting starred as bug 906793 for awhile now. Or starred and retriggered as b;r.
Actually, I mostly star them as "b" and don't retrigger, since we haven't been given any reason to believe anyone cares about the results enough to make it worth spending the money on retriggering them, while releng's constant shrieks about money and continual efforts to move to the cheapest, least reliable, most constrained AWS slaves make it seem like we're about out of money. Which might be one of your regression points, some change to cheap and incapable slaves.
A lot of those recent logs have crash stacks that look like legit crashes. If it was just the harness killing the process, the crash reason would be SIGABRT, not SIGSEGV. I'll file a separate bug to try and get some developer eyes on it (and to get away from tbplbot).
Oh, it's already filed as bug 975876. Looks like a fix just landed yesterday too.
Depends on: 975876
Depends on: 961013, 977269
I can't see a bare "Return code: 247" with no other failure line since comment 399 (2014-02-13); so looks like we're much better at actually catching timeouts and crashes since then. As such going to file some separate bugs for the things that have been dumped in here then close this out to stop it remaining a generic dumping ground.

Filed bug 1008254 for things like comment 585, the others that are more common look like they already have other bugs filed.
Status: NEW → RESOLVED
Closed: 10 years ago
Keywords: intermittent-failure
Resolution: --- → WORKSFORME
Summary: Intermittent B2G mochitest timeouts ("Return code: 247") → Intermittent B2G mochitest timeouts showing only "Return code: 247" in the summary
You need to log in before you can comment on or make changes to this bug.