Closed Bug 1941025 Opened 1 year ago Closed 1 year ago

Intermittent layout/style/test/test_dont_use_document_fonts.html (finished) | single tracking bug

Categories

(Core :: CSS Parsing and Computation, defect, P5)

Product:
Core
Component:
CSS Parsing and Computation
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, intermittent-testcase)

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

[task 2025-01-10T11:33:18.275Z] 11:33:18     INFO - TEST-START | layout/style/test/test_dont_use_document_fonts.html
[task 2025-01-10T11:33:18.334Z] 11:33:18     INFO - GECKO(3529) | MEMORY STAT | vsize 35898MB | residentFast 86MB | heapAllocated 9MB
[task 2025-01-10T11:33:18.348Z] 11:33:18     INFO - TEST-OK | layout/style/test/test_dont_use_document_fonts.html | took 72ms
[task 2025-01-10T11:39:28.483Z] 11:39:28     INFO - TEST-UNEXPECTED-TIMEOUT | layout/style/test/test_dont_use_document_fonts.html (finished) | application timed out after 370 seconds with no output
[task 2025-01-10T11:39:28.483Z] 11:39:28     INFO - TEST-INFO 
[task 2025-01-10T11:39:28.483Z] 11:39:28     INFO - Buffered messages finished
[task 2025-01-10T11:39:28.484Z] 11:39:28  WARNING - Force-terminating active process(es).
[task 2025-01-10T11:39:28.484Z] 11:39:28  WARNING - profiler Attempting to start the profiler to help with diagnosing the hang.
[task 2025-01-10T11:39:28.484Z] 11:39:28     INFO - profiler Sending SIGUSR1 to pid 3529 start the profiler.
[task 2025-01-10T11:39:28.485Z] 11:39:28     INFO - profiler Waiting 10s to capture a profile...
[task 2025-01-10T11:39:38.621Z] 11:39:38     INFO - profiler Sending SIGUSR2 to pid 3529 stop the profiler.
[task 2025-01-10T11:39:38.621Z] 11:39:38     INFO - profiler Wait 10s for Firefox to write the profile to disk.
[task 2025-01-10T11:39:48.770Z] 11:39:48     INFO - profiler Symbolicating profile in /opt/worker/tasks/task_173650788911099/build/blobber_upload_dir
[task 2025-01-10T11:39:48.770Z] 11:39:48     INFO - profiler Looking inside symbols dir: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/D32iwsUoRlq0FmSsQ9RcPg/artifacts/public/build/target.crashreporter-symbols.zip)
[task 2025-01-10T11:39:48.770Z] 11:39:48     INFO - profiler Symbolicating profile: /opt/worker/tasks/task_173650788911099/build/blobber_upload_dir/profile_0_3529.json
[task 2025-01-10T11:39:48.771Z] 11:39:48     INFO - profiler Symbolicating the performance profile... This could take a couple of minutes.
[task 2025-01-10T11:39:49.734Z] 11:39:49     INFO - Determining child pids from psutil...
[task 2025-01-10T11:39:49.741Z] 11:39:49     INFO - [3530, 3531, 3534, 3535, 3537, 3709, 3710, 3711]
[task 2025-01-10T11:39:49.741Z] 11:39:49     INFO - ==> process 3529 launched child process 3530
[task 2025-01-10T11:39:49.742Z] 11:39:49     INFO - ==> process 3529 launched child process 3531
<...>
[task 2025-01-10T11:43:50.929Z] 11:43:50     INFO - Not taking screenshot here: see the one that was previously logged
[task 2025-01-10T11:43:50.929Z] 11:43:50     INFO - Can't trigger Breakpad, just killing process
[task 2025-01-10T11:43:50.930Z] 11:43:50     INFO - Error: Failed to kill process 3583: process PID not found (pid=3583)
[task 2025-01-10T11:43:50.930Z] 11:43:50     INFO - Killing process: 3529
[task 2025-01-10T11:43:50.930Z] 11:43:50     INFO - Not taking screenshot here: see the one that was previously logged
[task 2025-01-10T11:43:50.931Z] 11:43:50     INFO - Can't trigger Breakpad, just killing process
[task 2025-01-10T11:43:50.931Z] 11:43:50     INFO - psutil found pid 3711 dead
[task 2025-01-10T11:43:50.931Z] 11:43:50     INFO - psutil found pid 3530 dead
[task 2025-01-10T11:43:50.932Z] 11:43:50     INFO - psutil found pid 3537 dead
[task 2025-01-10T11:43:50.932Z] 11:43:50     INFO - psutil found pid 3529 dead
[task 2025-01-10T11:43:50.932Z] 11:43:50     INFO - psutil found pid 3534 dead
[task 2025-01-10T11:43:50.933Z] 11:43:50     INFO - psutil found pid 3709 dead
[task 2025-01-10T11:43:50.933Z] 11:43:50     INFO - psutil found pid 3535 dead
[task 2025-01-10T11:43:50.933Z] 11:43:50     INFO - psutil found pid 3710 dead
[task 2025-01-10T11:43:50.934Z] 11:43:50     INFO - psutil found pid 3531 dead
[task 2025-01-10T11:43:50.934Z] 11:43:50     INFO - psutil found pid 3529 dead
[task 2025-01-10T11:43:50.934Z] 11:43:50     INFO - TEST-INFO | Main app process: killed by SIGTERM
[task 2025-01-10T11:43:50.935Z] 11:43:50     INFO - Buffered messages finished
[task 2025-01-10T11:43:50.935Z] 11:43:50     INFO - runtests.py | Application ran for: 0:11:08.414066
[task 2025-01-10T11:43:50.936Z] 11:43:50     INFO - zombiecheck | Reading PID log: /var/folders/sw/f7rp3gnn7c59ggfy93rxfx8c0000jb/T/tmppcejho_wpidlog
[task 2025-01-10T11:43:50.936Z] 11:43:50     INFO - ==> process 3529 launched child process 3530
[task 2025-01-10T11:43:50.936Z] 11:43:50     INFO - ==> process 3529 launched child process 3531
<...>
[task 2025-01-10T11:43:51.046Z] 11:43:51     INFO - zombiecheck | Checking for orphan process with PID: 3582
[task 2025-01-10T11:43:51.046Z] 11:43:51     INFO - zombiecheck | Checking for orphan process with PID: 3583
[task 2025-01-10T11:43:51.046Z] 11:43:51     INFO - runtests.py | Running with scheme: https
[task 2025-01-10T11:43:51.046Z] 11:43:51     INFO - runtests.py | Running with e10s: True
[task 2025-01-10T11:43:51.047Z] 11:43:51     INFO - runtests.py | Running with fission: True
[task 2025-01-10T11:43:51.047Z] 11:43:51     INFO - runtests.py | Running with cross-origin iframes: True
[task 2025-01-10T11:43:51.048Z] 11:43:51     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2025-01-10T11:43:51.048Z] 11:43:51     INFO - runtests.py | Running tests: start.
[task 2025-01-10T11:43:51.048Z] 11:43:51     INFO - 
[task 2025-01-10T11:43:51.048Z] 11:43:51     INFO - Application command: /opt/worker/tasks/task_173650788911099/build/application/Firefox Nightly.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/sw/f7rp3gnn7c59ggfy93rxfx8c0000jb/T/tmpwoun4r_l.mozrunner
[task 2025-01-10T11:43:51.049Z] 11:43:51     INFO - runtests.py | Application pid: 4159
[task 2025-01-10T11:43:51.049Z] 11:43:51     INFO - TEST-INFO | started process GECKO(4159)
[task 2025-01-10T11:43:51.148Z] 11:43:51     INFO - GECKO(4159) | 1736509431148	Marionette	INFO	Marionette enabled
[task 2025-01-10T11:43:51.451Z] 11:43:51     INFO - GECKO(4159) | 1736509431450	Marionette	TRACE	Received observer notification final-ui-startup
[task 2025-01-10T11:43:51.480Z] 11:43:51     INFO - GECKO(4159) | 1736509431479	Marionette	INFO	Listening on port 2828
[task 2025-01-10T11:43:51.481Z] 11:43:51     INFO - GECKO(4159) | 1736509431479	Marionette	DEBUG	Marionette is listening
[task 2025-01-10T11:43:51.579Z] 11:43:51     INFO - GECKO(4159) | 1736509431578	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:54514
[task 2025-01-10T11:43:51.583Z] 11:43:51     INFO - GECKO(4159) | 1736509431582	Marionette	DEBUG	Closed connection 0
[task 2025-01-10T11:43:51.584Z] 11:43:51     INFO - GECKO(4159) | 1736509431583	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:54515
[task 2025-01-10T11:43:51.858Z] 11:43:51     INFO - GECKO(4159) | 1736509431857	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2025-01-10T11:43:51.859Z] 11:43:51     INFO - GECKO(4159) | 1736509431858	Marionette	DEBUG	Waiting for initial application window
[task 2025-01-10T11:43:53.743Z] 11:43:53     INFO - GECKO(4159) | 1736509433742	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2025-01-10T11:43:53.749Z] 11:43:53     INFO - GECKO(4159) | 1736509433748	RemoteAgent	TRACE	[4] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2025-01-10T11:43:53.749Z] 11:43:53     INFO - GECKO(4159) | 1736509433748	RemoteAgent	TRACE	[4] ProgressListener Setting unload timer (5000ms)
[task 2025-01-10T11:43:53.750Z] 11:43:53     INFO - GECKO(4159) | 1736509433748	RemoteAgent	TRACE	[4] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2025-01-10T11:43:53.750Z] 11:43:53     INFO - GECKO(4159) | 1736509433748	RemoteAgent	TRACE	[4] Document already finished loading: about:blank
[task 2025-01-10T11:43:53.751Z] 11:43:53     INFO - GECKO(4159) | 1736509433748	RemoteAgent	TRACE	[4] ProgressListener Stop: has error=false url=about:blank
[task 2025-01-10T11:43:53.757Z] 11:43:53     INFO - GECKO(4159) | 1736509433754	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"5104bf2a-0db8-4987-a085-72f8c19b34b9","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"136.0a1","platformName":"mac","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:136.0) Gecko/20100101 Firefox/136.0","moz:buildID":"20250110002434","moz:headless":false,"moz:platformVersion":"23.6.0","moz:processID":4159,"moz:profile":"/var/folders/sw/f7rp3gnn7c59ggfy93rxfx8c0000jb/T/tmpwoun4r_l.mozrunner","moz:shutdownTimeout":60000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2025-01-10T11:43:53.767Z] 11:43:53     INFO - GECKO(4159) | 1736509433766	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/var/folders/sw/f7rp3gnn7c59ggfy93rxfx8c0000jb/T/tmpm3ed_k18.zip","temporary":false}]
[task 2025-01-10T11:43:53.882Z] 11:43:53     INFO - GECKO(4159) | 1736509433881	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2025-01-10T11:43:53.904Z] 11:43:53     INFO - GECKO(4159) | 1736509433903	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/var/folders/sw/f7rp3gnn7c59ggfy93rxfx8c0000jb/T/tmpppmt36f6.zip","temporary":false}]
[task 2025-01-10T11:43:53.926Z] 11:43:53     INFO - GECKO(4159) | 1736509433925	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2025-01-10T11:43:53.928Z] 11:43:53     INFO - GECKO(4159) | 1736509433927	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2025-01-10T11:43:53.928Z] 11:43:53     INFO - GECKO(4159) | 1736509433927	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2025-01-10T11:43:53.929Z] 11:43:53     INFO - GECKO(4159) | 1736509433928	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2025-01-10T11:43:53.929Z] 11:43:53     INFO - GECKO(4159) | 1736509433928	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2025-01-10T11:43:53.931Z] 11:43:53     INFO - GECKO(4159) | 1736509433929	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":"https://example.com:443/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Fvar%2Ffolders%2Fsw%2Ff7rp3gnn7c59ggfy93rxfx8c0000jb%2FT&cleanupCrashes=true&xOriginTests=true&ignorePrefsFile=ignorePrefs.json"}],"newSandbox":true,"sandbox":"default","line":2159,"filename":"tests/mochitest/runtests.py"}]
[task 2025-01-10T11:43:53.933Z] 11:43:53     INFO - GECKO(4159) | 1736509433932	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 4159
[task 2025-01-10T11:43:53.933Z] 11:43:53     INFO - GECKO(4159) | 1736509433932	Marionette	TRACE	[2] MarionetteCommands actor created for window id 4
[task 2025-01-10T11:43:53.938Z] 11:43:53     INFO - GECKO(4159) | 1736509433937	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2025-01-10T11:43:53.947Z] 11:43:53     INFO - GECKO(4159) | 1736509433946	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2025-01-10T11:43:53.947Z] 11:43:53     INFO - GECKO(4159) | 1736509433946	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2025-01-10T11:43:53.949Z] 11:43:53     INFO - GECKO(4159) | 1736509433949	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2025-01-10T11:43:53.950Z] 11:43:53     INFO - GECKO(4159) | 1736509433949	Marionette	TRACE	[2] MarionetteCommands actor destroyed for window id 4
[task 2025-01-10T11:43:53.951Z] 11:43:53     INFO - GECKO(4159) | 1736509433950	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2025-01-10T11:43:53.951Z] 11:43:53     INFO - runtests.py | Waiting for browser...
[task 2025-01-10T11:43:53.952Z] 11:43:53     INFO - GECKO(4159) | 1736509433951	Marionette	DEBUG	Closed connection 1
[task 2025-01-10T11:43:54.107Z] 11:43:54     INFO - SimpleTest START
[task 2025-01-10T11:43:54.108Z] 11:43:54     INFO - Dumping test context:
[task 2025-01-10T11:43:54.108Z] 11:43:54     INFO -   fission.autostart=true
[task 2025-01-10T11:43:54.109Z] 11:43:54     INFO - TEST-START | layout/style/test/test_bug1443344-1.html

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=493004568&repo=mozilla-central

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 1 year ago → 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.