1818258 - Intermittent /fs/FileSystemBaseHandle-postMessage-frames.https.window.html | single tracking bug

Status: RESOLVED INCOMPLETE

(Core :: DOM: File, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-02-22T15:20:32.485Z] 15:20:32     INFO - TEST-PASS | /fs/FileSystemBaseHandle-postMessage-frames.https.window.html | Send and receive messages using a blob iframe. 
[task 2023-02-22T15:20:32.485Z] 15:20:32     INFO - TEST-UNEXPECTED-TIMEOUT | /fs/FileSystemBaseHandle-postMessage-frames.https.window.html | Send and receive messages using an iframe srcdoc. - Test timed out
[task 2023-02-22T15:20:32.486Z] 15:20:32     INFO - TEST-UNEXPECTED-TIMEOUT | /fs/FileSystemBaseHandle-postMessage-frames.https.window.html | expected OK
[task 2023-02-22T15:20:32.486Z] 15:20:32     INFO - TEST-INFO took 60118ms
[task 2023-02-22T15:20:32.488Z] 15:20:32     INFO - PID 592 | 1677079232486	Marionette	INFO	Stopped listening on port 53168
[task 2023-02-22T15:20:35.782Z] 15:20:35     INFO - PID 592 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-02-22T15:20:35.787Z] 15:20:35     INFO - PID 592 |           Blocker:  Waiting for ping task
[task 2023-02-22T15:20:35.787Z] 15:20:35     INFO - PID 592 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-02-22T15:20:35.788Z] 15:20:35     INFO - PID 592 |           State: (none)
[task 2023-02-22T15:20:35.788Z] 15:20:35     INFO - PID 592 | 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 2023-02-22T15:20:35.789Z] 15:20:35     INFO - PID 592 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-22T15:20:35.790Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-22T15:20:35.790Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-22T15:20:35.791Z] 15:20:35     INFO - PID 592 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-22T15:20:35.792Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-22T15:20:35.793Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-22T15:20:35.794Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-22T15:20:35.794Z] 15:20:35     INFO - PID 592 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-22T15:20:35.795Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-22T15:20:35.795Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-22T15:20:35.796Z] 15:20:35     INFO - PID 592 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-22T15:20:35.797Z] 15:20:35     INFO - PID 592 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-22T15:20:35.797Z] 15:20:35     INFO - PID 592 | console.error: "TelemetryScheduler.shutdown - Already shut down"
[task 2023-02-22T15:20:35.800Z] 15:20:35     INFO - PID 592 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-02-22T15:20:35.801Z] 15:20:35     INFO - PID 592 |           Blocker:  Waiting for ping task
[task 2023-02-22T15:20:35.802Z] 15:20:35     INFO - PID 592 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-02-22T15:20:35.802Z] 15:20:35     INFO - PID 592 |           State: (none)
[task 2023-02-22T15:20:35.803Z] 15:20:35     INFO - PID 592 | 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 2023-02-22T15:20:35.803Z] 15:20:35     INFO - PID 592 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-22T15:20:35.804Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-22T15:20:35.804Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-22T15:20:35.805Z] 15:20:35     INFO - PID 592 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-22T15:20:35.805Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-22T15:20:35.806Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-22T15:20:35.807Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-22T15:20:35.808Z] 15:20:35     INFO - PID 592 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-22T15:20:35.808Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-22T15:20:35.809Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-22T15:20:35.809Z] 15:20:35     INFO - PID 592 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-22T15:20:35.810Z] 15:20:35     INFO - PID 592 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-22T15:20:35.810Z] 15:20:35     INFO - PID 592 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-02-22T15:20:35.811Z] 15:20:35     INFO - PID 592 |           Blocker:  TelemetryController: shutting down
[task 2023-02-22T15:20:35.811Z] 15:20:35     INFO - PID 592 |           Phase: profile-before-change-telemetry
[task 2023-02-22T15:20:35.812Z] 15:20:35     INFO - PID 592 |           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.sys.mjs:727:15
[task 2023-02-22T15:20:35.812Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-22T15:20:35.813Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-22T15:20:35.813Z] 15:20:35     INFO - PID 592 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-22T15:20:35.814Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-22T15:20:35.815Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-22T15:20:35.815Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-22T15:20:35.815Z] 15:20:35     INFO - PID 592 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-22T15:20:35.816Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-22T15:20:35.816Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-22T15:20:35.817Z] 15:20:35     INFO - PID 592 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-22T15:20:35.818Z] 15:20:35     INFO - PID 592 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-22T15:20:35.818Z] 15:20:35     INFO - PID 592 | 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 2023-02-22T15:20:35.819Z] 15:20:35     INFO - PID 592 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-22T15:20:35.819Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-22T15:20:35.820Z] 15:20:35     INFO - PID 592 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-22T15:20:35.820Z] 15:20:35     INFO - PID 592 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-22T15:20:35.821Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-22T15:20:35.822Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-22T15:20:35.822Z] 15:20:35     INFO - PID 592 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-22T15:20:35.823Z] 15:20:35     INFO - PID 592 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-22T15:20:35.823Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-22T15:20:35.824Z] 15:20:35     INFO - PID 592 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-22T15:20:35.824Z] 15:20:35     INFO - PID 592 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-22T15:20:35.825Z] 15:20:35     INFO - PID 592 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-22T15:20:35.916Z] 15:20:35     INFO - PID 592 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-22T15:20:35.922Z] 15:20:35     INFO - PID 592 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-22T15:20:35.924Z] 15:20:35     INFO - PID 592 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-22T15:20:35.925Z] 15:20:35     INFO - PID 592 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-22T15:20:35.927Z] 15:20:35     INFO - PID 592 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-22T15:20:35.985Z] 15:20:35     INFO - Browser exited with return code 0
[task 2023-02-22T15:20:35.990Z] 15:20:35     INFO - Closing logging queue
[task 2023-02-22T15:20:35.991Z] 15:20:35     INFO - queue closed
[task 2023-02-22T15:20:36.050Z] 15:20:36     INFO - Application command: Z:\task_167707722905082\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_167707722905082\AppData\Local\Temp\tmpvvib36ap
[task 2023-02-22T15:20:36.061Z] 15:20:36     INFO - PID 7596 | 1677079041725	Marionette	INFO	Marionette enabled
[task 2023-02-22T15:20:36.066Z] 15:20:36     INFO - PID 7596 | 1677079041728	Marionette	INFO	Listening on port 53186
[task 2023-02-22T15:20:36.067Z] 15:20:36     INFO - PID 7596 | JavaScript error: resource://gre/modules/XULStore.jsm, line 58: Error: Can't find profile directory.
[task 2023-02-22T15:20:36.068Z] 15:20:36     INFO - PID 7596 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_167707722905082\\AppData\\Local\\Temp\\tmpcfdxx82c\\search.json.mozlz4", (void 0)))
[task 2023-02-22T15:20:36.069Z] 15:20:36     INFO - PID 7596 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T15:20:36.069Z] 15:20:36     INFO - PID 7596 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T15:20:36.070Z] 15:20:36     INFO - PID 7596 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T15:20:36.071Z] 15:20:36     INFO - PID 7596 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T15:20:36.071Z] 15:20:36     INFO - Starting runner
[task 2023-02-22T15:20:37.089Z] 15:20:37     INFO - TEST-START | /fs/FileSystemBaseHandle-postMessage-windows.https.window.html

Comment 1

[Intermittent Failures Robot]

2 failures in 3643 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 1

Platform and build breakdown:

• windows10-32-2004-shippable-qr: 1
  • opt: 1
• windows10-32-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1818258&startday=2023-02-20&endday=2023-02-26&tree=all

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 3

[Treeherder Bug Filer]

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

Comment 4

[Intermittent Failures Robot]

1 failures in 2274 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• windows11-64-2009-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1818258&startday=2024-01-01&endday=2024-01-07&tree=all

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 6

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=448529404&repo=autoland

Comment 7

[Intermittent Failures Robot]

1 failures in 4052 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1818258&startday=2024-02-26&endday=2024-03-03&tree=all

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

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