Closed Bug 1927823 Opened 1 year ago Closed 13 days ago

Intermittent TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output

Categories

(Testing :: Mochitest, defect, P5)

defect

Tracking

(firefox-esr140 wontfix, firefox150 fixed, firefox151 fixed, firefox152 fixed)

RESOLVED FIXED
150 Branch
Tracking Status
firefox-esr140 --- wontfix
firefox150 --- fixed
firefox151 --- fixed
firefox152 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended])

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


[task 2024-10-29T10:49:33.728Z] 10:49:33     INFO - TEST-START | dom/media/test/test_vp9_superframes.html
[task 2024-10-29T10:49:36.100Z] 10:49:36     INFO - GECKO(4204) | MEMORY STAT | vsize 19414006MB | vsizeMaxContiguous 73248426MB | residentFast 1509MB
[task 2024-10-29T10:49:36.181Z] 10:49:36     INFO - TEST-OK | dom/media/test/test_vp9_superframes.html | took 2452ms
[task 2024-10-29T10:49:36.299Z] 10:49:36     INFO - TEST-START | Shutdown
[task 2024-10-29T10:49:36.300Z] 10:49:36     INFO - Passed:  11543
[task 2024-10-29T10:49:36.303Z] 10:49:36     INFO - Failed:  0
[task 2024-10-29T10:49:36.303Z] 10:49:36     INFO - Todo:    1
[task 2024-10-29T10:49:36.303Z] 10:49:36     INFO - Mode:    e10s
[task 2024-10-29T10:49:36.303Z] 10:49:36     INFO - Slowest: 210115ms - /tests/dom/media/test/test_playback.html
[task 2024-10-29T10:49:36.303Z] 10:49:36     INFO - SimpleTest FINISHED
[task 2024-10-29T10:49:36.304Z] 10:49:36     INFO - TEST-INFO | Ran 1 Loops
[task 2024-10-29T10:49:36.305Z] 10:49:36     INFO - SimpleTest FINISHED
[task 2024-10-29T10:49:36.415Z] 10:49:36     INFO - GECKO(4204) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 569: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2024-10-29T10:49:36.476Z] 10:49:36     INFO - GECKO(4204) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 569: NotFoundError: No such JSWindowActor 'AppTestDelegate'
[task 2024-10-29T10:49:36.478Z] 10:49:36     INFO - GECKO(4204) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 569: NotFoundError: No such JSWindowActor 'AppTestDelegate'
[task 2024-10-29T10:49:36.539Z] 10:49:36     INFO - GECKO(4204) | 1730198976537	Marionette	TRACE	Received observer notification quit-application
[task 2024-10-29T10:49:36.539Z] 10:49:36     INFO - GECKO(4204) | 1730198976538	Marionette	INFO	Stopped listening on port 2828
[task 2024-10-29T10:49:36.545Z] 10:49:36     INFO - GECKO(4204) | 1730198976543	Marionette	DEBUG	Marionette stopped listening
[task 2024-10-29T10:49:39.596Z] 10:49:39     INFO - TEST-INFO | Main app process: exit 0
[task 2024-10-29T10:49:39.600Z] 10:49:39     INFO - runtests.py | Application ran for: 0:08:55.143059
[task 2024-10-29T10:49:39.600Z] 10:49:39     INFO - zombiecheck | Reading PID log: C:\Users\task_173019602826454\AppData\Local\Temp\tmp61q69ieqpidlog
[task 2024-10-29T10:49:39.601Z] 10:49:39     INFO - ==> process 7432 launched child process 8844 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 3080 -prefsLen 25054 -prefMapHandle 3084 -prefMapSize 277786 -jsInitHandle 3088 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 3100 -initialChannelId {befafc36-a054-4f5a-9459-39d885a7a864} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 1 tab)
[task 2024-10-29T10:49:39.602Z] 10:49:39     INFO - ==> process 7432 launched child process 5388 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 3424 -prefsLen 26618 -prefMapHandle 3632 -prefMapSize 277786 -jsInitHandle 3636 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 3656 -initialChannelId {cbe5a7a1-fef5-43ae-8efe-6affab3d6ae0} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 2 tab)
[task 2024-10-29T10:49:39.603Z] 10:49:39     INFO - ==> process 7432 launched child process 1688 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 3896 -prefsLen 25573 -prefMapHandle 3900 -prefMapSize 277786 -jsInitHandle 3904 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 3868 -initialChannelId {3a5dd351-80aa-4112-a135-1f8bb1fb7921} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 3 tab)
[task 2024-10-29T10:49:39.604Z] 10:49:39     INFO - ==> process 7432 launched child process 7792 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -parentBuildID 20241029093541 -prefsHandle 4020 -prefsLen 27340 -prefMapHandle 4016 -prefMapSize 277786 -ipcHandle 4012 -initialChannelId {da507f4d-664a-4ad2-99b8-5e8ac536c08b} -parentPid 7432 -appDir "D:\task_173019602826454\build\application\firefox\browser" - 4 rdd)
[task 2024-10-29T10:49:39.606Z] 10:49:39     INFO - ==> process 7432 launched child process 4272 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 2768 -prefsLen 33181 -prefMapHandle 2772 -prefMapSize 277786 -jsInitHandle 2776 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 172 -initialChannelId {348fcd77-3771-4a10-9d25-2d9c6e6797da} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 5 tab)
[task 2024-10-29T10:49:39.606Z] 10:49:39     INFO - ==> process 7432 launched child process 6416 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -parentBuildID 20241029093541 -sandboxingKind 0 -prefsHandle 4676 -prefsLen 36131 -prefMapHandle 4720 -prefMapSize 277786 -ipcHandle 4756 -initialChannelId {8c5695ba-d977-4e96-b507-22877374c2ab} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 6 utility)
[task 2024-10-29T10:49:39.607Z] 10:49:39     INFO - ==> process 7432 launched child process 7588 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 5056 -prefsLen 33773 -prefMapHandle 5060 -prefMapSize 277786 -jsInitHandle 5064 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 4924 -initialChannelId {79dfed94-3e6b-4ac9-912b-0bc1fce588a3} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 7 tab)
[task 2024-10-29T10:49:39.609Z] 10:49:39     INFO - ==> process 7432 launched child process 6976 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 5084 -prefsLen 33773 -prefMapHandle 5184 -prefMapSize 277786 -jsInitHandle 5192 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 5064 -initialChannelId {982024f2-fd97-4753-95c3-2372a5e07c73} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 8 tab)
[task 2024-10-29T10:49:39.610Z] 10:49:39     INFO - ==> process 7432 launched child process 7164 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 5528 -prefsLen 36183 -prefMapHandle 5532 -prefMapSize 277786 -jsInitHandle 5536 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 5544 -initialChannelId {41366d5b-f133-4766-a229-7b51e9935adc} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 9 tab)
[task 2024-10-29T10:49:39.611Z] 10:49:39     INFO - ==> process 7432 launched child process 6548 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -isForBrowser -prefsHandle 5968 -prefsLen 33863 -prefMapHandle 196 -prefMapSize 277786 -jsInitHandle 4056 -jsInitLen 235232 -parentBuildID 20241029093541 -ipcHandle 4424 -initialChannelId {05048045-ddd2-4b16-9b42-16f4f5fb9067} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 10 tab)
[task 2024-10-29T10:49:39.612Z] 10:49:39     INFO - ==> process 7432 launched child process 5364 ("D:\task_173019602826454\build\application\firefox\firefox.exe" -contentproc -parentBuildID 20241029093541 -sandboxingKind 1 -prefsHandle 5968 -prefsLen 36481 -prefMapHandle 196 -prefMapSize 277786 -ipcHandle 4720 -initialChannelId {58dcf9ea-4438-41cf-b8d6-21bff2b95c17} -parentPid 7432 -win32kLockedDown -appDir "D:\task_173019602826454\build\application\firefox\browser" - 11 utility)
[task 2024-10-29T10:49:39.613Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 6976
[task 2024-10-29T10:49:39.613Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 7588
[task 2024-10-29T10:49:39.614Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8844
[task 2024-10-29T10:49:39.614Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 5388
[task 2024-10-29T10:49:39.615Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 7792
[task 2024-10-29T10:49:39.615Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 4272
[task 2024-10-29T10:49:39.616Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 6416
[task 2024-10-29T10:49:39.616Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 6548
[task 2024-10-29T10:49:39.617Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 5364
[task 2024-10-29T10:49:39.617Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 1688
[task 2024-10-29T10:49:39.618Z] 10:49:39     INFO - zombiecheck | Checking for orphan process with PID: 7164
[task 2024-10-29T10:49:39.618Z] 10:49:39     INFO - runtests.py | Running with scheme: https
[task 2024-10-29T10:49:39.619Z] 10:49:39     INFO - runtests.py | Running with e10s: True
[task 2024-10-29T10:49:39.619Z] 10:49:39     INFO - runtests.py | Running with fission: True
[task 2024-10-29T10:49:39.620Z] 10:49:39     INFO - runtests.py | Running with cross-origin iframes: False
[task 2024-10-29T10:49:39.620Z] 10:49:39     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2024-10-29T10:49:39.620Z] 10:49:39     INFO - runtests.py | Running tests: start.
[task 2024-10-29T10:49:39.620Z] 10:49:39     INFO - 
[task 2024-10-29T10:49:39.689Z] 10:49:39     INFO - Application command: D:\task_173019602826454\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile C:\Users\task_173019602826454\AppData\Local\Temp\tmpxla37lwr.mozrunner
[task 2024-10-29T10:49:39.710Z] 10:49:39     INFO - runtests.py | Application pid: 9888
[task 2024-10-29T10:49:39.710Z] 10:49:39     INFO - TEST-INFO | started process GECKO(9888)
[task 2024-10-29T10:49:40.393Z] 10:49:40     INFO - GECKO(9888) | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: VendorIDMismatch V 0xb 0x1414 (t=6.78926) [GFX1-]: VendorIDMismatch V 0xb 0x1414
[task 2024-10-29T10:52:39.711Z] 10:52:39     INFO - runtests.py | Waiting for browser...
[task 2024-10-29T10:55:50.410Z] 10:55:50     INFO - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output
[task 2024-10-29T10:55:50.410Z] 10:55:50     INFO - TEST-INFO 
[task 2024-10-29T10:55:50.411Z] 10:55:50     INFO - Buffered messages finished
[task 2024-10-29T10:55:50.412Z] 10:55:50  WARNING - Force-terminating active process(es).
[task 2024-10-29T10:55:50.412Z] 10:55:50     INFO - profiler Not sending a signal to start the profiler - not on MacOS or Linux. See Bug 1823370.
[task 2024-10-29T10:55:50.413Z] 10:55:50     INFO - Determining child pids from psutil...
[task 2024-10-29T10:55:50.414Z] 10:55:50     INFO - [5316]
[task 2024-10-29T10:55:50.415Z] 10:55:50     INFO - Found child pids: {5316}
[task 2024-10-29T10:55:50.415Z] 10:55:50     INFO - Killing process: 5316
[task 2024-10-29T10:55:50.415Z] 10:55:50     INFO - TEST-INFO | started process screenshot
[task 2024-10-29T10:55:50.551Z] 10:55:50     INFO - TEST-INFO | screenshot: exit 0
[task 2024-10-29T10:55:50.566Z] 10:55:50     INFO - Can't trigger Breakpad, just killing process
[task 2024-10-29T10:55:50.613Z] 10:55:50     INFO - psutil found pid 5316 dead
[task 2024-10-29T10:55:50.618Z] 10:55:50     INFO - psutil found pid 5316 dead
[task 2024-10-29T10:55:50.619Z] 10:55:50     INFO - Killing process: 9888
[task 2024-10-29T10:55:50.619Z] 10:55:50     INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-10-29T10:55:50.619Z] 10:55:50     INFO - Can't trigger Breakpad, just killing process
[task 2024-10-29T10:55:50.625Z] 10:55:50     INFO - Error: Failed to kill process 9888: process no longer exists (pid=9888)
[task 2024-10-29T10:55:50.627Z] 10:55:50     INFO - psutil found pid 9888 dead
[task 2024-10-29T10:55:50.627Z] 10:55:50     INFO - TEST-INFO | Main app process: exit f
[task 2024-10-29T10:55:50.628Z] 10:55:50     INFO - Buffered messages finished
[task 2024-10-29T10:55:50.628Z] 10:55:50     INFO - runtests.py | Application ran for: 0:06:10.937510
[task 2024-10-29T10:55:50.628Z] 10:55:50     INFO - zombiecheck | Reading PID log: C:\Users\task_173019602826454\AppData\Local\Temp\tmpeeqznrbwpidlog
[task 2024-10-29T10:55:50.630Z] 10:55:50     INFO -  Traceback (most recent call last):
[task 2024-10-29T10:55:50.630Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\tests\mochitest\runtests.py", line 3786, in doTests
[task 2024-10-29T10:55:50.630Z] 10:55:50     INFO -      ret, _ = self.runApp(
[task 2024-10-29T10:55:50.631Z] 10:55:50     INFO -               ^^^^^^^^^^^^
[task 2024-10-29T10:55:50.631Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\tests\mochitest\runtests.py", line 3046, in runApp
[task 2024-10-29T10:55:50.631Z] 10:55:50     INFO -      six.reraise(exc, value, tb)
[task 2024-10-29T10:55:50.631Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\six.py", line 719, in reraise
[task 2024-10-29T10:55:50.632Z] 10:55:50     INFO -      raise value
[task 2024-10-29T10:55:50.632Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\tests\mochitest\runtests.py", line 2905, in runApp
[task 2024-10-29T10:55:50.632Z] 10:55:50     INFO -      self.marionette.start_session()
[task 2024-10-29T10:55:50.632Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2024-10-29T10:55:50.633Z] 10:55:50     INFO -      m._handle_socket_failure()
[task 2024-10-29T10:55:50.633Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\marionette_driver\marionette.py", line 820, in _handle_socket_failure
[task 2024-10-29T10:55:50.633Z] 10:55:50     INFO -      reraise(exc_cls, exc, tb)
[task 2024-10-29T10:55:50.633Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\six.py", line 719, in reraise
[task 2024-10-29T10:55:50.634Z] 10:55:50     INFO -      raise value
[task 2024-10-29T10:55:50.634Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2024-10-29T10:55:50.634Z] 10:55:50     INFO -      return func(*args, **kwargs)
[task 2024-10-29T10:55:50.634Z] 10:55:50     INFO -             ^^^^^^^^^^^^^^^^^^^^^
[task 2024-10-29T10:55:50.634Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\marionette_driver\marionette.py", line 1368, in start_session
[task 2024-10-29T10:55:50.635Z] 10:55:50     INFO -      self.raise_for_port(timeout=timeout)
[task 2024-10-29T10:55:50.635Z] 10:55:50     INFO -    File "D:\task_173019602826454\build\venv\Lib\site-packages\marionette_driver\marionette.py", line 744, in raise_for_port
[task 2024-10-29T10:55:50.635Z] 10:55:50     INFO -      raise socket.timeout(
[task 2024-10-29T10:55:50.635Z] 10:55:50     INFO -  TimeoutError: Timed out waiting for connection on 127.0.0.1:2828!
[task 2024-10-29T10:55:50.636Z] 10:55:50    ERROR - Automation Error: Received unexpected exception while running application
[task 2024-10-29T10:55:50.636Z] 10:55:50    ERROR - 
[task 2024-10-29T10:55:50.637Z] 10:55:50     INFO - Stopping web server
[task 2024-10-29T10:55:50.637Z] 10:55:50     INFO - Server shut down.
[task 2024-10-29T10:55:50.638Z] 10:55:50     INFO - Web server killed.
[task 2024-10-29T10:55:50.638Z] 10:55:50     INFO - Stopping web socket server
[task 2024-10-29T10:55:50.639Z] 10:55:50     INFO - Stopping ssltunnel
[task 2024-10-29T10:55:50.639Z] 10:55:50     INFO - Stopping websocket/process bridge
[task 2024-10-29T10:55:50.639Z] 10:55:50     INFO - runtests.py | Running tests: end.
[task 2024-10-29T10:55:50.639Z] 10:55:50     INFO - Buffered messages finished
[task 2024-10-29T10:55:50.639Z] 10:55:50     INFO - Running manifest: dom/media/test/mochitest_bugs.toml
[task 2024-10-29T10:55:50.651Z] 10:55:50     INFO - INFO | runtests.py | ASan using symbolizer at D:\task_173019602826454\build\application\firefox\llvm-symbolizer.exe
[task 2024-10-29T10:55:52.332Z] 10:55:52     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-10-29T10:55:52.864Z] 10:55:52     INFO - PID 2668 | D:\task_173019602826454\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL
[task 2024-10-29T10:55:52.864Z] 10:55:52     INFO - 
[task 2024-10-29T10:55:52.957Z] 10:55:52     INFO - INFO | runtests.py | ASan using symbolizer at D:\task_173019602826454\build\application\firefox\llvm-symbolizer.exe
[task 2024-10-29T10:55:54.584Z] 10:55:54     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-10-29T10:55:54.595Z] 10:55:54     INFO - INFO | runtests.py | ASan using symbolizer at D:\task_173019602826454\build\application\firefox\llvm-symbolizer.exe
[task 2024-10-29T10:55:56.181Z] 10:55:56     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-10-29T10:55:56.201Z] 10:55:56     INFO - MochitestServer : launching ['D:\\task_173019602826454\\build\\tests\\bin\\xpcshell.exe', '-g', 'D:\\task_173019602826454\\build\\application\\firefox', '-e', "const _PROFILE_PATH = 'C:\\\\Users\\\\task_173019602826454\\\\AppData\\\\Local\\\\Temp\\\\tmpz_mhc508.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false; const _HTTPD_PATH = 'D:\\\\task_173019602826454\\\\build\\\\tests\\\\bin\\\\components';", '-f', 'D:\\task_173019602826454\\build\\tests\\mochitest\\server.js']
[task 2024-10-29T10:55:56.202Z] 10:55:56     INFO - runtests.py | Server pid: 1304
[task 2024-10-29T10:55:56.208Z] 10:55:56     INFO - runtests.py | Websocket server pid: 9652
[task 2024-10-29T10:55:56.212Z] 10:55:56     INFO - runtests.py | websocket/process bridge pid: 3284
[task 2024-10-29T10:55:57.228Z] 10:55:57     INFO - INFO | runtests.py | ASan using symbolizer at D:\task_173019602826454\build\application\firefox\llvm-symbolizer.exe
[task 2024-10-29T10:55:58.947Z] 10:55:58     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2024-10-29T10:55:58.954Z] 10:55:58     INFO - runtests.py | SSL tunnel pid: 7992
[task 2024-10-29T10:55:58.954Z] 10:55:58     INFO - use http3 server: 0
[task 2024-10-29T10:55:58.955Z] 10:55:58     INFO - runtests.py | Running with scheme: http
[task 2024-10-29T10:55:58.955Z] 10:55:58     INFO - runtests.py | Running with e10s: True
[task 2024-10-29T10:55:58.956Z] 10:55:58     INFO - runtests.py | Running with fission: True
[task 2024-10-29T10:55:58.957Z] 10:55:58     INFO - runtests.py | Running with cross-origin iframes: False
[task 2024-10-29T10:55:58.957Z] 10:55:58     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2024-10-29T10:55:58.958Z] 10:55:58     INFO - runtests.py | Running tests: start.
[task 2024-10-29T10:55:58.958Z] 10:55:58     INFO - 
[task 2024-10-29T10:55:59.057Z] 10:55:59     INFO - Application command: D:\task_173019602826454\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile C:\Users\task_173019602826454\AppData\Local\Temp\tmpz_mhc508.mozrunner
[task 2024-10-29T10:55:59.077Z] 10:55:59     INFO - runtests.py | Application pid: 7996
[task 2024-10-29T10:55:59.077Z] 10:55:59     INFO - TEST-INFO | started process GECKO(7996)
[task 2024-10-29T10:56:00.418Z] 10:56:00     INFO - GECKO(7996) | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: VendorIDMismatch V 0xb 0x1414 (t=13.3189) [GFX1-]: VendorIDMismatch V 0xb 0x1414
[task 2024-10-29T10:56:00.637Z] 10:56:00     INFO - GECKO(7996) | 1730199360651	Marionette	INFO	Marionette enabled
[task 2024-10-29T10:56:00.653Z] 10:56:00     INFO - GECKO(7996) | 1730199360659	Marionette	TRACE	Received observer notification final-ui-startup
[task 2024-10-29T10:56:00.887Z] 10:56:00     INFO - GECKO(7996) | console.error: "Warning: unrecognized command line flag" "-foreground"
[task 2024-10-29T10:56:01.028Z] 10:56:01     INFO - GECKO(7996) | 1730199361028	Marionette	INFO	Listening on port 2828
[task 2024-10-29T10:56:01.039Z] 10:56:01     INFO - GECKO(7996) | 1730199361038	Marionette	DEBUG	Marionette is listening
[task 2024-10-29T10:56:01.090Z] 10:56:01     INFO - GECKO(7996) | 1730199361094	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:51535
[task 2024-10-29T10:56:01.137Z] 10:56:01     INFO - GECKO(7996) | 1730199361151	Marionette	DEBUG	Closed connection 0
[task 2024-10-29T10:56:01.889Z] 10:56:01     INFO - GECKO(7996) | 1730199361893	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:51537
[task 2024-10-29T10:56:02.201Z] 10:56:02     INFO - GECKO(7996) | 1730199362204	Marionette	DEBUG	Closed connection 1
[task 2024-10-29T10:56:02.295Z] 10:56:02     INFO - GECKO(7996) | 1730199362308	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:51544
[task 2024-10-29T10:56:02.577Z] 10:56:02     INFO - GECKO(7996) | 1730199362564	Marionette	DEBUG	Closed connection 2
[task 2024-10-29T10:56:02.577Z] 10:56:02     INFO - GECKO(7996) | 1730199362566	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:51545
[task 2024-10-29T10:56:02.687Z] 10:56:02     INFO - GECKO(7996) | 1730199362688	Marionette	DEBUG	3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-10-29T10:56:02.719Z] 10:56:02     INFO - GECKO(7996) | 1730199362718	Marionette	DEBUG	Waiting for initial application window
[task 2024-10-29T10:56:10.847Z] 10:56:10     INFO - GECKO(7996) | [ERROR error_support::handling] logins-unexpected: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:10.848Z] 10:56:10     INFO - GECKO(7996) | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:10.872Z] 10:56:10     INFO - GECKO(7996) | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error for Amo: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-10-29T10:56:10.880Z] 10:56:10     INFO - GECKO(7996) | [ERROR error_support::handling] logins-unexpected: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:10.881Z] 10:56:10     INFO - GECKO(7996) | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:10.933Z] 10:56:10     INFO - GECKO(7996) | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error for Amp: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-10-29T10:56:11.025Z] 10:56:11     INFO - GECKO(7996) | [ERROR error_support::handling] logins-unexpected: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:11.025Z] 10:56:11     INFO - GECKO(7996) | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:11.026Z] 10:56:11     INFO - GECKO(7996) | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error for Wikipedia: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-10-29T10:56:11.033Z] 10:56:11     INFO - GECKO(7996) | [ERROR error_support::handling] logins-unexpected: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:11.034Z] 10:56:11     INFO - GECKO(7996) | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:11.035Z] 10:56:11     INFO - GECKO(7996) | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error for Mdn: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-10-29T10:56:11.060Z] 10:56:11     INFO - GECKO(7996) | 1730199371059	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2024-10-29T10:56:11.103Z] 10:56:11     INFO - GECKO(7996) | 1730199371102	RemoteAgent	TRACE	[11] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2024-10-29T10:56:11.103Z] 10:56:11     INFO - GECKO(7996) | 1730199371102	RemoteAgent	TRACE	[11] ProgressListener Setting unload timer (40000ms)
[task 2024-10-29T10:56:11.107Z] 10:56:11     INFO - GECKO(7996) | 1730199371106	RemoteAgent	TRACE	[11] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2024-10-29T10:56:11.108Z] 10:56:11     INFO - GECKO(7996) | 1730199371106	RemoteAgent	TRACE	[11] Document already finished loading: about:blank
[task 2024-10-29T10:56:11.108Z] 10:56:11     INFO - GECKO(7996) | 1730199371106	RemoteAgent	TRACE	[11] ProgressListener Stop: has error=false url=about:blank
[task 2024-10-29T10:56:11.177Z] 10:56:11     INFO - GECKO(7996) | 1730199371174	Marionette	DEBUG	3 <- [1,1,null,{"sessionId":"6756c70c-6c94-4cd6-86a2-f972b35cc46c","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"134.0a1","platformName":"windows","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:134.0) Gecko/20100101 Firefox/134.0","moz:buildID":"20241029093541","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":3772,"moz:profile":"C:\\Users\\task_173019602826454\\AppData\\Local\\Temp\\tmpz_mhc508.mozrunner","moz:shutdownTimeout":300000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2024-10-29T10:56:11.241Z] 10:56:11     INFO - GECKO(7996) | [ERROR error_support::handling] logins-unexpected: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:11.242Z] 10:56:11     INFO - GECKO(7996) | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-10-29T10:56:11.242Z] 10:56:11     INFO - GECKO(7996) | 1730199371240	Marionette	DEBUG	3 -> [0,2,"Addon:Install",{"path":"C:\\Users\\task_173019602826454\\AppData\\Local\\Temp\\tmpi4asjsco.zip","temporary":false}]
[task 2024-10-29T10:56:11.253Z] 10:56:11     INFO - GECKO(7996) | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error for Yelp: Error from Remote Settings: Remote settings error: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-10-29T10:56:11.566Z] 10:56:11     INFO - GECKO(7996) | 1730199371565	Marionette	DEBUG	3 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2024-10-29T10:56:11.610Z] 10:56:11     INFO - GECKO(7996) | 1730199371609	Marionette	DEBUG	3 -> [0,3,"Addon:Install",{"path":"C:\\Users\\task_173019602826454\\AppData\\Local\\Temp\\tmpws3a65iw.zip","temporary":false}]
[task 2024-10-29T10:56:11.692Z] 10:56:11     INFO - GECKO(7996) | 1730199371692	Marionette	DEBUG	3 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2024-10-29T10:56:11.699Z] 10:56:11     INFO - GECKO(7996) | 1730199371698	Marionette	DEBUG	3 -> [0,4,"Marionette:GetContext",{}]
[task 2024-10-29T10:56:11.699Z] 10:56:11     INFO - GECKO(7996) | 1730199371698	Marionette	DEBUG	3 <- [1,4,null,{"value":"content"}]
[task 2024-10-29T10:56:11.701Z] 10:56:11     INFO - GECKO(7996) | 1730199371700	Marionette	DEBUG	3 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-10-29T10:56:11.702Z] 10:56:11     INFO - GECKO(7996) | 1730199371702	Marionette	DEBUG	3 <- [1,5,null,{"value":null}]
[task 2024-10-29T10:56:11.707Z] 10:56:11     INFO - GECKO(7996) | 1730199371704	Marionette	DEBUG	3 -> [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=C%3A%5CUsers%5Ctask_173019602826454%5CAppData%5CLocal%5CTemp&cleanupCrashes=true&ignorePrefsFile=ignorePrefs.json"}],"newSandbox":true,"sandbox":"default","line":2169,"filename":"D:\\task_173019602826454\\build\\tests\\mochitest\\runtests.py"}]
[task 2024-10-29T10:56:11.737Z] 10:56:11     INFO - GECKO(7996) | 1730199371737	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 3772
[task 2024-10-29T10:56:11.746Z] 10:56:11     INFO - GECKO(7996) | 1730199371745	Marionette	TRACE	[2] MarionetteCommands actor created for window id 4
[task 2024-10-29T10:56:11.788Z] 10:56:11     INFO - GECKO(7996) | 1730199371788	Marionette	DEBUG	3 <- [1,6,null,{"value":null}]
[task 2024-10-29T10:56:11.833Z] 10:56:11     INFO - GECKO(7996) | 1730199371830	Marionette	DEBUG	3 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2024-10-29T10:56:11.834Z] 10:56:11     INFO - GECKO(7996) | 1730199371830	Marionette	DEBUG	3 <- [1,7,null,{"value":null}]
[task 2024-10-29T10:56:11.869Z] 10:56:11     INFO - GECKO(7996) | 1730199371868	Marionette	DEBUG	3 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2024-10-29T10:56:11.870Z] 10:56:11     INFO - GECKO(7996) | 1730199371870	Marionette	TRACE	[2] MarionetteCommands actor destroyed for window id 4
[task 2024-10-29T10:56:11.883Z] 10:56:11     INFO - GECKO(7996) | 1730199371883	Marionette	DEBUG	3 <- [1,8,null,{"value":null}]
[task 2024-10-29T10:56:11.926Z] 10:56:11     INFO - runtests.py | Waiting for browser...
[task 2024-10-29T10:56:11.938Z] 10:56:11     INFO - GECKO(7996) | 1730199371937	Marionette	DEBUG	Closed connection 3
[task 2024-10-29T10:56:12.748Z] 10:56:12     INFO - SimpleTest START
[task 2024-10-29T10:56:12.750Z] 10:56:12     INFO - Dumping test context:
[task 2024-10-29T10:56:12.750Z] 10:56:12     INFO -   fission.autostart=true
[task 2024-10-29T10:56:12.764Z] 10:56:12     INFO - TEST-START | dom/media/test/test_bug1113600.html

This is basically what we have as bug 1414495. Not sure if it makes sense to track ASAN separately anymore or if we should combine both bugs.

Component: Task Configuration → Mochitest
Product: Firefox Build System → Testing
Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended]

As it looks like the infra changes as pushed to macOS workers on bug 2004631 reduced the number of failures for that platform.

Depends on: 2004631

The same underlying fixes for bug 2013816 have fixed this failure as well. No more failures on trunk, beta and release down to version 150. Only the 140 ESR is still affected so leaving the flag set appropriately.

Status: NEW → RESOLVED
Closed: 13 days ago
Depends on: 2013816
No longer depends on: 1930443
Resolution: --- → FIXED
Target Milestone: --- → 150 Branch
You need to log in before you can comment on or make changes to this bug.