Open Bug 1894562 Opened 2 months ago Updated 26 minutes ago

Intermittent runtests.py | single tracking bug

Categories

(Testing :: Mochitest, defect, P5)

defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, intermittent-testcase)

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=456587199&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/K_terAATQ5iIPzFWEEOIUQ/runs/0/artifacts/public/logs/live_backing.log


[task 2024-05-01T21:36:11.348Z] 21:36:11     INFO - TEST-START | ipc/glue/test/browser/test_utility_audio_on.html
[task 2024-05-01T21:36:11.348Z] 21:36:11     INFO - TEST-SKIP | ipc/glue/test/browser/test_utility_audio_on.html | took 0ms
[task 2024-05-01T21:36:11.349Z] 21:36:11     INFO - Running manifest: dom/media/mediasession/test/mochitest.toml
[task 2024-05-01T21:36:11.409Z] 21:36:11     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2024-05-01T21:36:15.421Z] 21:36:15     INFO -  error: XDG_RUNTIME_DIR not set in the environment.
[task 2024-05-01T21:36:21.263Z] 21:36:21     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-05-01T21:36:21.263Z] 21:36:21     INFO - UBSan enabled.
[task 2024-05-01T21:36:39.188Z] 21:36:39     INFO -  Setting pipeline to PAUSED ...
[task 2024-05-01T21:36:39.189Z] 21:36:39     INFO -  Pipeline is PREROLLING ...
[task 2024-05-01T21:36:39.190Z] 21:36:39     INFO -  Pipeline is PREROLLED ...
[task 2024-05-01T21:36:39.191Z] 21:36:39     INFO -  Setting pipeline to PLAYING ...
[task 2024-05-01T21:36:39.191Z] 21:36:39     INFO -  New clock: GstSystemClock
[task 2024-05-01T21:36:39.224Z] 21:36:39     INFO -  Got EOS from element "pipeline0".
[task 2024-05-01T21:36:39.224Z] 21:36:39     INFO -  Execution ended after 0:00:00.033472973
[task 2024-05-01T21:36:39.224Z] 21:36:39     INFO -  Setting pipeline to PAUSED ...
[task 2024-05-01T21:36:39.224Z] 21:36:39     INFO -  Setting pipeline to READY ...
[task 2024-05-01T21:36:39.227Z] 21:36:39     INFO -  (gst-launch-1.0:1052): GStreamer-CRITICAL **: 21:36:39.224: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2024-05-01T21:36:39.228Z] 21:36:39     INFO -  Setting pipeline to NULL ...
[task 2024-05-01T21:36:39.228Z] 21:36:39     INFO -  Freeing pipeline ...
[task 2024-05-01T21:36:39.967Z] 21:36:39     INFO - PID 1073 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2024-05-01T21:36:39.967Z] 21:36:39     INFO - 
[task 2024-05-01T21:36:39.981Z] 21:36:39     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2024-05-01T21:36:39.985Z] 21:36:39     INFO - LSan enabled.
[task 2024-05-01T21:36:39.986Z] 21:36:39     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-05-01T21:36:39.988Z] 21:36:39     INFO - UBSan enabled.
[task 2024-05-01T21:36:39.988Z] 21:36:39     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2024-05-01T21:36:39.990Z] 21:36:39     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-05-01T21:36:39.991Z] 21:36:39     INFO - UBSan enabled.
[task 2024-05-01T21:36:39.994Z] 21:36:39     INFO - MochitestServer : launching ['/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-e', "const _PROFILE_PATH = '/tmp/tmpyuwjp46h.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false; const _HTTPD_PATH = '/builds/worker/workspace/build/tests/bin/components';", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2024-05-01T21:36:39.994Z] 21:36:39     INFO - runtests.py | Server pid: 1078
[task 2024-05-01T21:36:39.997Z] 21:36:39     INFO - runtests.py | Websocket server pid: 1079
[task 2024-05-01T21:36:40.007Z] 21:36:40     INFO - runtests.py | websocket/process bridge pid: 1080
[task 2024-05-01T21:36:49.945Z] 21:36:49    ERROR - runtests.py | Timed out while waiting for websocket/process bridge startup.
[task 2024-05-01T21:36:49.947Z] 21:36:49     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2024-05-01T21:36:49.951Z] 21:36:49     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-05-01T21:36:49.952Z] 21:36:49     INFO - UBSan enabled.
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | SSL tunnel pid: 1104
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - use http3 server: 0
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running with scheme: http
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running with e10s: True
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running with fission: True
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running with cross-origin iframes: False
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2024-05-01T21:36:49.957Z] 21:36:49     INFO - runtests.py | Running tests: start.
[task 2024-05-01T21:36:49.958Z] 21:36:49     INFO - 
[task 2024-05-01T21:36:49.968Z] 21:36:49     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpyuwjp46h.mozrunner
[task 2024-05-01T21:36:49.975Z] 21:36:49     INFO - runtests.py | Application pid: 1109
[task 2024-05-01T21:36:49.976Z] 21:36:49     INFO - TEST-INFO | started process GECKO(1109)
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: ManageChildProcess(glxtest): failed to read data from child process:  (t=19.5017) [GFX1-]: ManageChildProcess(glxtest): failed to read data from child process:
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: ManageChildProcess(glxtest): failed to read data from child process:  (t=19.5017) |[1][GFX1-]: timeout (t=19.5017) [GFX1-]: timeout
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: ManageChildProcess(glxtest): failed to read data from child process:  (t=19.5017) |[1][GFX1-]: timeout (t=19.5017) |[2][GFX1-]: glxtest: ManageChildProcess failed
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) |  (t=19.5017) [GFX1-]: glxtest: ManageChildProcess failed
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: ManageChildProcess(glxtest): failed to read data from child process:  (t=19.5017) |[1][GFX1-]: timeout (t=19.5017) |[2][GFX1-]: glxtest: ManageChildProcess failed
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) |  (t=19.5017) |[3][GFX1-]: No GPUs detected via PCI
[task 2024-05-01T21:37:09.470Z] 21:37:09     INFO - GECKO(1109) |  (t=19.5017) [GFX1-]: No GPUs detected via PCI
[task 2024-05-01T21:37:26.191Z] 21:37:26     INFO - GECKO(1109) | 1714599446190	Marionette	INFO	Marionette enabled
[task 2024-05-01T21:37:26.197Z] 21:37:26     INFO - GECKO(1109) | 1714599446196	Marionette	TRACE	Received observer notification final-ui-startup
[task 2024-05-01T21:37:26.336Z] 21:37:26     INFO - GECKO(1109) | console.error: "Warning: unrecognized command line flag" "-foreground"
[task 2024-05-01T21:37:26.447Z] 21:37:26     INFO - GECKO(1109) | 1714599446446	Marionette	INFO	Listening on port 2828
[task 2024-05-01T21:37:26.454Z] 21:37:26     INFO - GECKO(1109) | 1714599446453	Marionette	DEBUG	Marionette is listening
[task 2024-05-01T21:37:26.485Z] 21:37:26     INFO - GECKO(1109) | 1714599446484	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:58276
[task 2024-05-01T21:37:26.542Z] 21:37:26     INFO - GECKO(1109) | 1714599446541	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:58278
[task 2024-05-01T21:37:26.548Z] 21:37:26     INFO - GECKO(1109) | 1714599446541	Marionette	DEBUG	Closed connection 0
[task 2024-05-01T21:37:38.038Z] 21:37:38     INFO - GECKO(1109) | 1714599458037	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-05-01T21:37:38.052Z] 21:37:38     INFO - GECKO(1109) | 1714599458050	Marionette	DEBUG	Waiting for initial application window
[task 2024-05-01T21:37:43.680Z] 21:37:43     INFO - GECKO(1109) | console.error: ({})
[task 2024-05-01T21:37:46.896Z] 21:37:46     INFO - GECKO(1109) | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-05-01T21:37:46.900Z] 21:37:46     INFO - GECKO(1109) | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error: Error from Remote Settings: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-05-01T21:37:47.720Z] 21:37:47     INFO - GECKO(1109) | 1714599467719	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2024-05-01T21:37:47.774Z] 21:37:47     INFO - GECKO(1109) | 1714599467772	RemoteAgent	TRACE	[9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2024-05-01T21:37:47.776Z] 21:37:47     INFO - GECKO(1109) | 1714599467773	RemoteAgent	TRACE	[9] ProgressListener Setting unload timer (40000ms)
[task 2024-05-01T21:37:47.786Z] 21:37:47     INFO - GECKO(1109) | 1714599467784	RemoteAgent	TRACE	[9] Document already finished loading: about:blank
[task 2024-05-01T21:37:47.791Z] 21:37:47     INFO - GECKO(1109) | 1714599467785	RemoteAgent	TRACE	[9] ProgressListener Stop: has error=false
[task 2024-05-01T21:37:47.860Z] 21:37:47     INFO - GECKO(1109) | 1714599467858	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"1b6fb713-b7b6-4d4c-8baf-5d2b95df1c1b","capabilities":{"browserName":"firefox","browserVersion":"127.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:127.0) Gecko/20100101 Firefox/127.0","moz:accessibilityChecks":false,"moz:buildID":"20240501202727","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":1109,"moz:profile":"/tmp/tmpyuwjp46h.mozrunner","moz:shutdownTimeout":300000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2024-05-01T21:37:47.922Z] 21:37:47     INFO - GECKO(1109) | 1714599467921	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmphtaw_lm0.zip","temporary":false}]
[task 2024-05-01T21:37:48.317Z] 21:37:48     INFO - GECKO(1109) | 1714599468315	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2024-05-01T21:37:48.392Z] 21:37:48     INFO - GECKO(1109) | 1714599468391	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpmbsk5mk1.zip","temporary":false}]
[task 2024-05-01T21:37:48.501Z] 21:37:48     INFO - GECKO(1109) | 1714599468500	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2024-05-01T21:37:48.545Z] 21:37:48     INFO - GECKO(1109) | 1714599468544	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2024-05-01T21:37:48.548Z] 21:37:48     INFO - GECKO(1109) | 1714599468545	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2024-05-01T21:37:48.554Z] 21:37:48     INFO - GECKO(1109) | 1714599468553	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-05-01T21:37:48.558Z] 21:37:48     INFO - GECKO(1109) | 1714599468553	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2024-05-01T21:37:48.563Z] 21:37:48     INFO - GECKO(1109) | 1714599468560	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"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 distr ... s which flavor and url to load.\nlet ev = new CustomEvent(\"mochitest-load\", { detail: [flavor, url] });\nwin.dispatchEvent(ev);","args":[{"flavor":"mochitest","testUrl":"http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true&ignorePrefsFile=ignorePrefs.json"}],"newSandbox":true,"sandbox":"default","line":2167,"filename":"tests/mochitest/runtests.py"}]
[task 2024-05-01T21:37:48.588Z] 21:37:48     INFO - GECKO(1109) | 1714599468587	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 1109
[task 2024-05-01T21:37:48.605Z] 21:37:48     INFO - GECKO(1109) | 1714599468604	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2024-05-01T21:37:48.696Z] 21:37:48     INFO - GECKO(1109) | 1714599468695	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2024-05-01T21:37:48.777Z] 21:37:48     INFO - GECKO(1109) | 1714599468776	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2024-05-01T21:37:48.783Z] 21:37:48     INFO - GECKO(1109) | 1714599468782	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2024-05-01T21:37:48.926Z] 21:37:48     INFO - GECKO(1109) | 1714599468924	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 13
[task 2024-05-01T21:37:48.977Z] 21:37:48     INFO - GECKO(1109) | 1714599468976	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2024-05-01T21:37:48.985Z] 21:37:48     INFO - GECKO(1109) | 1714599468984	Marionette	TRACE	[1] MarionetteCommands actor destroyed for window id 2
[task 2024-05-01T21:37:48.999Z] 21:37:48     INFO - GECKO(1109) | 1714599468998	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2024-05-01T21:37:49.013Z] 21:37:49     INFO - runtests.py | Waiting for browser...
[task 2024-05-01T21:37:49.019Z] 21:37:49     INFO - GECKO(1109) | 1714599469017	Marionette	DEBUG	Closed connection 1
[task 2024-05-01T21:37:49.909Z] 21:37:49     INFO - SimpleTest START
[task 2024-05-01T21:37:49.912Z] 21:37:49     INFO - Dumping test context:
[task 2024-05-01T21:37:49.913Z] 21:37:49     INFO -   fission.autostart=true
[task 2024-05-01T21:37:49.935Z] 21:37:49     INFO - TEST-START | dom/media/mediasession/test/test_setactionhandler.html
You need to log in before you can comment on or make changes to this bug.