Closed Bug 1802230 Opened 3 years ago Closed 2 years ago

Intermittent /resize-observer/svg.html | single tracking bug

Categories

(Core :: Layout, defect, P5)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, intermittent-testcase)

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

[task 2022-11-23T21:27:49.798Z] 21:27:49     INFO - TEST-START | /resize-observer/svg.html
[task 2022-11-23T21:27:49.799Z] 21:27:49     INFO - Closing window e2de5826-35e4-4a29-b8c5-ec569b3aeee6
[task 2022-11-23T21:28:00.002Z] 21:28:00     INFO - 
[task 2022-11-23T21:28:00.002Z] 21:28:00     INFO - TEST-PASS | /resize-observer/svg.html | ResizeObserver implemented 
[task 2022-11-23T21:28:00.002Z] 21:28:00     INFO - TEST-UNEXPECTED-NOTRUN | /resize-observer/svg.html | guard - expected PASS
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - 
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - TEST-UNEXPECTED-FAIL | /resize-observer/svg.html | test0: observe svg:circle - assert_unreached: Timed out waiting for notification. (1000ms) Reached unreachable code
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - _handleTimeout/</<@http://web-platform.test:8000/resize-observer/resources/resizeTestHelper.js:123:27
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2590:25
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - _handleTimeout/<@http://web-platform.test:8000/resize-observer/resources/resizeTestHelper.js:122:27
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2590:25
[task 2022-11-23T21:28:00.003Z] 21:28:00     INFO - _handleTimeout@http://web-platform.test:8000/resize-observer/resources/resizeTestHelper.js:117:23
[task 2022-11-23T21:28:00.004Z] 21:28:00     INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:2710:25
[task 2022-11-23T21:28:00.004Z] 21:28:00     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2590:25
[task 2022-11-23T21:28:00.004Z] 21:28:00     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:2637:35
[task 2022-11-23T21:28:00.004Z] 21:28:00     INFO - TEST-UNEXPECTED-TIMEOUT | /resize-observer/svg.html | expected OK
[task 2022-11-23T21:28:00.004Z] 21:28:00     INFO - TEST-INFO took 10205ms
[task 2022-11-23T21:28:00.009Z] 21:28:00     INFO - Restarting browser for new test group
[task 2022-11-23T21:28:00.011Z] 21:28:00     INFO - PID 2630 | 1669238880010	Marionette	INFO	Stopped listening on port 57306
[task 2022-11-23T21:28:00.099Z] 21:28:00     INFO - PID 2630 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-23T21:28:00.100Z] 21:28:00     INFO - PID 2630 |           Blocker:  Waiting for ping task
[task 2022-11-23T21:28:00.100Z] 21:28:00     INFO - PID 2630 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-23T21:28:00.101Z] 21:28:00     INFO - PID 2630 |           State: (none)
[task 2022-11-23T21:28:00.101Z] 21:28:00     INFO - PID 2630 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.102Z] 21:28:00     INFO - PID 2630 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-23T21:28:00.103Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-23T21:28:00.103Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-23T21:28:00.104Z] 21:28:00     INFO - PID 2630 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-23T21:28:00.104Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-23T21:28:00.104Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-23T21:28:00.105Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-23T21:28:00.105Z] 21:28:00     INFO - PID 2630 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-23T21:28:00.106Z] 21:28:00     INFO - PID 2630 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-23T21:28:00.106Z] 21:28:00     INFO - PID 2630 | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
[task 2022-11-23T21:28:00.107Z] 21:28:00     INFO - PID 2630 | send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
[task 2022-11-23T21:28:00.107Z] 21:28:00     INFO - PID 2630 | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-23T21:28:00.108Z] 21:28:00     INFO - PID 2630 | sendPing@resource://gre/modules/EventPing.jsm:51:30
[task 2022-11-23T21:28:00.108Z] 21:28:00     INFO - PID 2630 | _submitPing@resource://gre/modules/EventPing.jsm:229:12
[task 2022-11-23T21:28:00.109Z] 21:28:00     INFO - PID 2630 | shutdown@resource://gre/modules/EventPing.jsm:112:10
[task 2022-11-23T21:28:00.109Z] 21:28:00     INFO - PID 2630 | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:940:31
[task 2022-11-23T21:28:00.110Z] 21:28:00     INFO - PID 2630 | shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1010:24
[task 2022-11-23T21:28:00.110Z] 21:28:00     INFO - PID 2630 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-23T21:28:00.111Z] 21:28:00     INFO - PID 2630 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-23T21:28:00.111Z] 21:28:00     INFO - PID 2630 |           Blocker:  Waiting for ping task
[task 2022-11-23T21:28:00.112Z] 21:28:00     INFO - PID 2630 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-23T21:28:00.112Z] 21:28:00     INFO - PID 2630 |           State: (none)
[task 2022-11-23T21:28:00.113Z] 21:28:00     INFO - PID 2630 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.113Z] 21:28:00     INFO - PID 2630 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-23T21:28:00.114Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-23T21:28:00.114Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-23T21:28:00.115Z] 21:28:00     INFO - PID 2630 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-23T21:28:00.115Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-23T21:28:00.116Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-23T21:28:00.116Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-23T21:28:00.117Z] 21:28:00     INFO - PID 2630 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-23T21:28:00.117Z] 21:28:00     INFO - PID 2630 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-23T21:28:00.118Z] 21:28:00     INFO - PID 2630 | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
[task 2022-11-23T21:28:00.118Z] 21:28:00     INFO - PID 2630 | send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
[task 2022-11-23T21:28:00.119Z] 21:28:00     INFO - PID 2630 | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-23T21:28:00.119Z] 21:28:00     INFO - PID 2630 | saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:982:34
[task 2022-11-23T21:28:00.120Z] 21:28:00     INFO - PID 2630 | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
[task 2022-11-23T21:28:00.120Z] 21:28:00     INFO - PID 2630 | cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
[task 2022-11-23T21:28:00.121Z] 21:28:00     INFO - PID 2630 | shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
[task 2022-11-23T21:28:00.121Z] 21:28:00     INFO - PID 2630 | shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
[task 2022-11-23T21:28:00.122Z] 21:28:00     INFO - PID 2630 | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:959:35
[task 2022-11-23T21:28:00.122Z] 21:28:00     INFO - PID 2630 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-23T21:28:00.123Z] 21:28:00     INFO - PID 2630 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-23T21:28:00.123Z] 21:28:00     INFO - PID 2630 |           Blocker:  TelemetryController: shutting down
[task 2022-11-23T21:28:00.124Z] 21:28:00     INFO - PID 2630 |           Phase: profile-before-change-telemetry
[task 2022-11-23T21:28:00.124Z] 21:28:00     INFO - PID 2630 |           State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-23T21:28:00.125Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-23T21:28:00.125Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-23T21:28:00.126Z] 21:28:00     INFO - PID 2630 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-23T21:28:00.126Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-23T21:28:00.127Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-23T21:28:00.127Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-23T21:28:00.128Z] 21:28:00     INFO - PID 2630 | getShutdownState@resource://gre/modules/TelemetrySend.jsm:1687:7
[task 2022-11-23T21:28:00.128Z] 21:28:00     INFO - PID 2630 | getShutdownState@resource://gre/modules/TelemetrySend.jsm:369:30
[task 2022-11-23T21:28:00.129Z] 21:28:00     INFO - PID 2630 | _getState@resource://gre/modules/TelemetryControllerParent.jsm:1058:38
[task 2022-11-23T21:28:00.129Z] 21:28:00     INFO - PID 2630 | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.jsm:917:18
[task 2022-11-23T21:28:00.130Z] 21:28:00     INFO - PID 2630 | safeGetState@resource://gre/modules/AsyncShutdown.jsm:242:17
[task 2022-11-23T21:28:00.130Z] 21:28:00     INFO - PID 2630 | Barrier/addBlocker/promise<@resource://gre/modules/AsyncShutdown.jsm:751:20
[task 2022-11-23T21:28:00.131Z] 21:28:00     INFO - PID 2630 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-23T21:28:00.131Z] 21:28:00     INFO - PID 2630 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.132Z] 21:28:00     INFO - PID 2630 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-23T21:28:00.132Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-23T21:28:00.133Z] 21:28:00     INFO - PID 2630 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-23T21:28:00.133Z] 21:28:00     INFO - PID 2630 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-23T21:28:00.134Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-23T21:28:00.134Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-23T21:28:00.135Z] 21:28:00     INFO - PID 2630 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-23T21:28:00.135Z] 21:28:00     INFO - PID 2630 | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:721:5
[task 2022-11-23T21:28:00.136Z] 21:28:00     INFO - PID 2630 | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:249:17
[task 2022-11-23T21:28:00.136Z] 21:28:00     INFO - PID 2630 | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1235:42
[task 2022-11-23T21:28:00.137Z] 21:28:00     INFO - PID 2630 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-23T21:28:00.394Z] 21:28:00     INFO - PID 2630 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.395Z] 21:28:00     INFO - PID 2630 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.396Z] 21:28:00     INFO - PID 2630 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.396Z] 21:28:00     INFO - PID 2630 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.397Z] 21:28:00     INFO - PID 2630 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-23T21:28:00.441Z] 21:28:00     INFO - Browser exited with return code 0
[task 2022-11-23T21:28:00.444Z] 21:28:00     INFO - Closing logging queue
[task 2022-11-23T21:28:00.444Z] 21:28:00     INFO - queue closed
[task 2022-11-23T21:28:00.465Z] 21:28:00     INFO - Application command: /opt/worker/tasks/task_166923768985830/build/application/Firefox.app/Contents/MacOS/firefox --marionette about:blank -foreground -profile /var/folders/1c/7gz26xcj1xb1vwr7p52qhtcm000014/T/tmpfnhtpij0
[task 2022-11-23T21:28:00.472Z] 21:28:00     INFO - PID 2664 | 1669238863895	Marionette	INFO	Marionette enabled
[task 2022-11-23T21:28:00.473Z] 21:28:00     INFO - PID 2664 | 1669238863919	Marionette	INFO	Listening on port 58616
[task 2022-11-23T21:28:00.474Z] 21:28:00     INFO - PID 2664 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /var/folders/1c/7gz26xcj1xb1vwr7p52qhtcm000014/T/tmpwla33ra6/search.json.mozlz4", (void 0)))
[task 2022-11-23T21:28:00.474Z] 21:28:00     INFO - Starting runner
[task 2022-11-23T21:28:00.778Z] 21:28:00     INFO - PID 2664 | 2022-11-23 21:28:00.776 firefox[2664:73047] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.firefox.savedState/window_1.data: No such file or directory (2)
[task 2022-11-23T21:28:01.067Z] 21:28:01     INFO - TEST-START | /scroll-animations/css/animation-shorthand.html

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

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