Closed Bug 1050022 Opened 11 years ago Closed 10 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: 10 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: