Closed Bug 1050022 Opened 10 years ago Closed 9 years ago

[B2G Emulator] Intermittent ogg-video/clipping-1a.html | application timed out after 330 seconds with no output, resulting from test being first in reftest-14 instead of near end of reftest-13

Categories

(Core :: Layout, defect)

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

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: KWierso, Assigned: jwwang)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

diff in the list of reftests run in reftest-14 triggered by d997e5accc3f
65.15 KB, patch
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=45371388&tree=Mozilla-Inbound
b2g_emulator_vm mozilla-inbound opt test reftest-14 on 2014-08-06 16:13:01 PDT for push e8b07667f3cc

slave: tst-linux64-spot-495



16:17:34     INFO -  ***
16:17:34     INFO -  *****************************************************************
16:17:34     INFO -  1407366991366	Marionette	INFO	marionette enabled via build flag and pref
16:17:34     INFO -  1407366993817	Marionette	INFO	marionette-server.js loaded
16:17:34     INFO -  1407366995081	Marionette	INFO	B2G emulator: yes
16:17:34     INFO -  1407366995095	Marionette	INFO	Device detected is generic
16:17:34     INFO -  1407366995098	Marionette	INFO	Bypassing offline status.
16:17:34     INFO -  1407366995119	Marionette	INFO	Listening on port 2828
16:17:34     INFO -  1407366995127	Marionette	INFO	Marionette server ready
16:17:34     INFO -  System JS : WARNING resource://gre/modules/Preferences.jsm:378 - mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create
16:17:34     INFO -  1407366997840	Marionette	DEBUG	accepted connection on 127.0.0.1:33253
16:17:35     INFO -  1407366999042	Marionette	DEBUG	accepted connection on 127.0.0.1:33254
16:17:35     INFO -  1407367046292	Marionette	INFO	loaded marionette-listener.js
16:17:35     INFO -  1407367046316	Marionette	INFO	sendToClient: {"from":"0","value":{"browserName":"B2G","browserVersion":"34.0a1","platformName":"ANDROID","platformVersion":"34.0a1","handlesAlerts":false,"nativeEvents":false,"rotatable":true,"secureSsl":false,"takesElementScreenshot":true,"takesScreenshot":true,"platform":"ANDROID","XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","appBuildId":"20140806155350","device":"qemu","version":"34.0a1","b2g":true}}, {9383b44b-00e2-47f5-afb3-aa7454eff4aa}, {9383b44b-00e2-47f5-afb3-aa7454eff4aa}
16:17:35     INFO -  ###################################### forms.js loaded
16:17:35     INFO -  ############################### browserElementPanning.js loaded
16:17:35     INFO -  ######################## BrowserElementChildPreload.js loaded
16:17:35     INFO -  1407367047784	Marionette	DEBUG	Got request: setContext, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"34.0a1","takesScreenshot":true,"appBuildId":"20140806155350","XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"34.0a1","device":"qemu","b2g":true,"nativeEvents":false,"platformVersion":"34.0a1","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"setContext","parameters":{"value":"chrome"}}, id: {f5cc8ad9-e4fd-4fdb-80c5-67dd1845e2f6}
16:17:35     INFO -  1407367047792	Marionette	INFO	sendToClient: {"from":"0","ok":true}, {f5cc8ad9-e4fd-4fdb-80c5-67dd1845e2f6}, {f5cc8ad9-e4fd-4fdb-80c5-67dd1845e2f6}
16:24:42     INFO -  1407367049245	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"34.0a1","takesScreenshot":true,"appBuildId":"20140806155350","XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"34.0a1","device":"qemu","b2g":true,"nativeEvents":false,"platformVersion":"34.0a1","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"executeScript","parameters":{"scriptTimeout":null,"specialPowers":false,"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\nfunction setDefaultPrefs() {\n    // This code sets the preferences for extension-based reftest.\n    var prefs = Cc[\"@mozilla.org/preferences-service;1\"].\n                getService(Ci.nsIPrefService);\n    var branch = prefs.getDefaultBranch(\"\");\n\n    // For mochitests, we're more interested in testing the behavior of in-\n    // content XBL bindings, so we set this pref to true. In reftests, we're\n    // more interested in testing the behavior of XBL as it works in chrome,\n    // so we want this pref to be false.\n    branch.setBoolPref(\"dom.use_xbl_scopes_for_remote_xul\", false);\n    branch.setBoolPref(\"gfx.color_management.force_srgb\", true);\n    branch.setBoolPref(\"browser.dom.window.dump.enabled\", true);\n    branch.setIntPref(\"ui.caretBlinkTime\", -1);\n    branch.setBoolPref(\"dom.send_after_paint_to_content\", true);\n    // no slow script dialogs\n    branch.setIntPref(\"dom.max_script_run_time\", 0);\n    branch.setIntPref(\"dom.max_chrome_script_run_time\", 0);\n    branch.setIntPref(\"hangmonitor.timeout\", 0);\n    // Ensure autoplay is enabled for all platforms.\n    branch.setBoolPref(\"media.autoplay.enabled\", true);\n    // Disable updates\n    branch.setBoolPref(\"app.update.enabled\", false);\n    // Disable addon updates and prefetching so we don't leak them\n    branch.setBoolPref(\"extensions.update.enabled\", false);\n    branch.setBoolPref(\"extensions.getAddons.cache.enabled\", false);\n    // Disable blocklist updates so we don't have them reported as leaks\n    branch.setBoolPref(\"extensions.blocklist.enabled\", false);\n    // Make url-classifier updates so rare that they won't affect tests\n    branch.setIntPref(\"urlclassifier.updateinterval\", 172800);\n    // Disable high-quality downscaling, since it makes reftests more difficult.\n    branch.setBoolPref(\"image.high_quality_downscaling.enabled\", false);\n    // Checking whether two files are the same is slow on Windows.\n    // Setting this pref makes tests run much faster there.\n    branch.setBoolPref(\"security.fileuri.strict_origin_policy\", false);\n    // Disable the thumbnailing service\n    branch.setBoolPref(\"browser.pagethumbnails.capturing_disabled\", true);\n    // Since our tests are 800px wide, set the assume-designed-for width of all\n    // pages to be 800px (instead of the default of 980px). This ensures that\n    // in our 800px window we don't zoom out by default to try to fit the\n    // assumed 980px content.\n    branch.setIntPref(\"browser.viewport.desktopWidth\", 800);\n    // Disable the fade out (over time) of overlay scrollbars, since we\n    // can't guarantee taking both reftest snapshots at the same point\n    // during the fade.\n    branch.setBoolPref(\"layout.testing.overlay-scrollbars.always-visible\", true);\n    // Disable interruptible reflow since (1) it's normally not going to\n    // happen, but (2) it might happen if we somehow end up with both\n    // pending user events and clock skew.  So to avoid having to change\n    // MakeProgress to deal with waiting for interruptible reflows to\n    // complete for a rare edge case, we just disable interruptible\n    // reflow so that that rare edge case doesn't lead to reftest\n    // failures.\n    branch.setBoolPref(\"layout.interruptible-reflow.enabled\", false);\n    // Disable the auto-hide feature of touch caret to avoid potential\n    // intermittent issues.\n    branch.setIntPref(\"touchcaret.expiration.time\", 0);\n//@line 12 \"/builds/slave/b2g_m-in_emu_dep-0000000000000/build/gecko/layout/tools/reftest/b2g_start_script.js\"\n}\n\nfunction setPermissions() {\n  if (__marionetteParams.length < 2) {\n    return;\n  }\n\n  let serverAddr = __marionetteParams[0];\n  let serverPort = __marionetteParams[1];\n  let perms = Cc[\"@mozilla.org/permissionmanager;1\"]\n              .getService(Ci.nsIPermissionManager);\n  let ioService = Cc[\"@mozilla.org/network/io-service;1\"]\n                  .getService(Ci.nsIIOService);\n  let uri = ioService.newURI(\"http://\" + serverAddr + \":\" + serverPort, null, null);\n  perms.add(uri, \"allowXULXBL\", Ci.nsIPermissionManager.ALLOW_ACTION);\n}\n\nlet cm = Cc[\"@mozilla.org/categorymanager;1\"]\n           .getService(Components.interfaces.nsICategoryManager);\n\n// Disable update timers that cause b2g failures.\nif (cm) {\n  cm.deleteCategoryEntry(\"update-timer\", \"WebappsUpdateTimer\", false);\n  cm.deleteCategoryEntry(\"update-timer\", \"nsUpdateService\", false);\n}\n\n// Load into any existing windows\nlet wm = Cc[\"@mozilla.org/appshell/window-mediator;1\"]\n            .getService(Ci.nsIWindowMediator);\nlet win = wm.getMostRecentWindow('');\n\n// Set preferences and permissions\nsetDefaultPrefs();\nsetPermissions();\n\n// Loading this into the global namespace causes intermittent failures.\n// See bug 882888 for more details.\nlet reftest = {};\nCu.import(\"chrome://reftest/content/reftest.jsm\", reftest);\n\n// Start the reftests\nreftest.OnRefTestLoad(win);\n","newSandbox":true,"args":["10.0.2.2",8888],"filename":"b2gautomation.py","line":283}}, id: {19cde534-939e-4038-8a13-f13c4bf7b9de}
16:24:42     INFO -  REFTEST INFO | Failed to find the test-plugin.
16:24:42     INFO -  REFTEST INFO | Failed to find the test-plugin.
16:24:42     INFO -  REFTEST INFO | Could not get test plugin tags.
16:24:42     INFO -  1407367050311	Marionette	INFO	sendToClient: {"from":"0","value":null}, {19cde534-939e-4038-8a13-f13c4bf7b9de}, {19cde534-939e-4038-8a13-f13c4bf7b9de}
16:24:42     INFO -  System JS : ERROR chrome://marionette/content/marionette-listener.js:195 - TypeError: content is null
16:24:42     INFO -  JavaScript error: chrome://b2g/content/shell.js, line 591: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXPCComponents_Utils.cloneInto]
16:24:42     INFO -  [Parent 662] WARNING: waitpid failed pid:722 errno:10: file ../../../gecko/ipc/chromium/src/base/process_util_posix.cc, line 261
16:24:42     INFO -  JavaScript error: chrome://b2g/content/shell.js, line 591: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXPCComponents_Utils.cloneInto]
16:24:42     INFO -  ###################################### forms.js loaded
16:24:42     INFO -  ############################### browserElementPanning.js loaded
16:24:42     INFO -  ######################## BrowserElementChildPreload.js loaded
16:24:42     INFO -  REFTEST INFO | Dumping JSON representation of sandbox
16:24:42     INFO -  REFTEST INFO | {"isDebugBuild":false,"xulRuntime":{"widgetToolkit":"gonk","OS":"Android","__exposedProps__":{"widgetToolkit":"r","OS":"r","XPCOMABI":"r","shell":"r"},"XPCOMABI":"arm-eabi-gcc3"},"smallScreen":false,"d2d":false,"azureQuartz":false,"azureSkia":true,"skiaContent":false,"azureSkiaGL":1,"contentSameGfxBackendAsCanvas":false,"layersGPUAccelerated":true,"layersOpenGL":true,"layersOMTC":true,"B2G":true,"B2GDT":false,"Android":false,"cocoaWidget":false,"gtk2Widget":false,"qtWidget":false,"winWidget":false,"AddressSanitizer":false,"webrtc":true,"http":{"__exposedProps__":{"userAgent":"r","appName":"r","appVersion":"r","vendor":"r","vendorSub":"r","product":"r","productSub":"r","platform":"r","oscpu":"r","language":"r","misc":"r"},"userAgent":"Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0","appName":"Mozilla","appVersion":"5.0","platform":"","oscpu":"","misc":"rv:34.0"},"OSX":0,"haveTestPlugin":false,"windowsDefaultTheme":false,"nativeThemePref":false,"prefs":{"__exposedProps__":{"getBoolPref":"r","getIntPref":"r"},"_prefs":{"root":"","PREF_INVALID":0,"PREF_STRING":32,"PREF_INT":64,"PREF_BOOL":128}},"browserIsRemote":true,"asyncPanZoom":true}
16:24:42     INFO -  REFTEST INFO | Discovered 11108 tests, after filtering SKIP tests, we have 9828
16:24:42     INFO -  REFTEST INFO | Running chunk 14 out of 20 chunks.  tests 7334-7894/561
16:24:42     INFO -  REFTEST TEST-START | http://10.0.2.2:8888/tests/layout/reftests/ogg-video/clipping-1a.html
16:24:42     INFO -  REFTEST TEST-LOAD | http://10.0.2.2:8888/tests/layout/reftests/ogg-video/clipping-1a.html | 0 / 561 (0%)
16:24:42     INFO -  REFTEST INFO | [CONTENT] Using browser remote=true
16:24:42     INFO -  REFTEST INFO | drawWindow flags = DRAWWINDOW_DRAW_CARET | DRAWWINDOW_DRAW_VIEW | DRAWWINDOW_USE_WIDGET_LAYERS; window size = 800,1000; test browser size = 800,1000
16:24:42     INFO -  REFTEST TEST-LOAD | http://10.0.2.2:8888/tests/layout/reftests/ogg-video/clipping-1-ref.html | 0 / 561 (0%)
16:24:42  WARNING -  TEST-UNEXPECTED-FAIL | http://10.0.2.2:8888/tests/layout/reftests/ogg-video/clipping-1a.html | application timed out after 330 seconds with no output
16:24:42     INFO -  checking for crashes in '/data/local/tests/reftest/profile/minidumps'
16:24:42     INFO -  INFO | automation.py | Application ran for: 0:08:21.195908
16:24:42     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpm20fUMpidlog
16:24:42     INFO -  checking for crashes in '/data/local/tests/reftest/profile/minidumps'
16:24:42     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
16:24:42     INFO -  REFTEST INFO | runreftest.py | Running tests: end.
16:24:42    ERROR - Return code: 1
16:24:42     INFO - dumping logcat
16:24:42     INFO - Running command: ['cat', '/builds/slave/test/build/emulator-5554.log']
16:24:42     INFO - Copy/paste: cat /builds/slave/test/build/emulator-5554.log
16:24:42     INFO -  08-06 23:14:24.654 I/qemu-props(   35): connected to 'boot-properties' qemud service.
16:24:42     INFO -  08-06 23:14:24.654 I/qemu-props(   35): receiving..
16:24:42     INFO -  08-06 23:14:24.714 I/DEBUG   (   37): debuggerd: Aug  6 2014 17:07:09
16:24:42     INFO -  08-06 23:14:24.897 I/qemu-props(   35): received: dalvik.vm.heapsize=48m
16:24:42     INFO -  08-06 23:14:25.054 I/qemu-props(   35): receiving..
16:24:42     INFO -  08-06 23:14:25.054 I/qemu-props(   35): received: qemu.sf.lcd_density=160
16:24:42     INFO -  08-06 23:14:25.054 I/qemu-props(   35): receiving..
So far it looks like it's a "regression" from:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d997e5accc3f

If that's the case, I think the most likely explanation is that it's an existing problem that was exposed by a change in the division of the reftests into their 15 chunks.
So that changeset pushed this test from the end of reftest-13 to being the very first test in reftest-14.
One other thing to note from the logs is that the hang appears to be while loading the reference; the test has been loaded and screenshotted.
(In reply to David Baron [:dbaron] (UTC-7) (needinfo? for questions) from comment #50)
> I should probably retrigger some reftest-13 to check that theory, though:

So far the theory holds based on:

https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=d997e5accc3f&jobname=b2g_emulator_vm%20mozilla-inbound%20opt%20test%20reftest-1[34]

(just look at the top 2 pushes)
(It would be really nice if the B2G automation gave us stacks for hangs.  (Or at least screenshots, although that might not be so helpful.)
Summary: Intermittent ogg-video/clipping-1a.html | application timed out after 330 seconds with no output → [B2G Emulator] Intermittent ogg-video/clipping-1a.html | application timed out after 330 seconds with no output, resulting from test being first in reftest-14 instead of near end of reftest-13
I don't see a clear person to blame here, but this is a pretty bad intermittent failure and would be good to fix ASAP.  Wondering if you know who might be able to help debug?
Flags: needinfo?(ajones)
JW - would you be willing to add this bug to your queue?
Flags: needinfo?(ajones) → needinfo?(jwwang)
Sure.
Assignee: nobody → jwwang
Flags: needinfo?(jwwang)
The problem seems to just go away after I tried to add some debugging logs...

Try results:
https://tbpl.mozilla.org/?tree=Try&rev=203fe4ebfb15

and the logs I added:
http://hg.stage.mozaws.net/mirrors/generaldelta/try/rev/203fe4ebfb15

This is strange. I wonder if it is a problem of the test framework.
Given the TBPLbot comments here, looks like it went away on its own a day or so ago. FWIW, we're tracking down another similar issue in bug 1053495 that looks like it may be tied to chunking changes (i.e. new reftests added, test starts timing out frequently).
It sounds similar to bug 1047268 where I added some tests and broke test_dirs.html for permission was changed.

It really looks like a problem in the test framework where adding/disabling tests or changing the order of tests would affect the execution environment (permission and the like) of the tests.
We know that adding/removing tests changes which tests are in which chunks.  The question is why this test fails when it's at the beginning of a reftest chunk; to fix this bug you would need to diagnose and fix the cause.
(In reply to David Baron [:dbaron] (UTC+2) (needinfo? for questions) (away/busy until Sep 11) from comment #84)
> We know that adding/removing tests changes which tests are in which chunks. 
> The question is why this test fails when it's at the beginning of a reftest
> chunk; to fix this bug you would need to diagnose and fix the cause.

On top of that, I added only logs (comment 79) without changing the test order would also make the problem go away. So I still have no clue where it got stuck.
Inactive; closing (see bug 1180138).
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: