Closed Bug 1825517 Opened 2 years ago Closed 2 years ago

Intermittent /service-workers/service-worker/data-transfer-files.https.html | single tracking bug

Categories

(Core :: DOM: Service Workers, defect, P5)

Product:
Core
Component:
DOM: Service Workers
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, intermittent-testcase)

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

[task 2023-03-30T09:35:44.784Z] 09:35:44     INFO - TEST-OK | /service-workers/service-worker/data-iframe.html | took 282ms
[task 2023-03-30T09:35:44.795Z] 09:35:44     INFO - TEST-START | /service-workers/service-worker/data-transfer-files.https.html
[task 2023-03-30T09:35:44.797Z] 09:35:44     INFO - Setting pref dom.serviceWorkers.mitigations.bypass_on_fault to true
[task 2023-03-30T09:35:44.803Z] 09:35:44     INFO - Setting pref dom.serviceWorkers.enabled to true
[task 2023-03-30T09:35:44.812Z] 09:35:44     INFO - Setting pref dom.serviceWorkers.mitigations.bypass_on_fault to false
[task 2023-03-30T09:35:44.822Z] 09:35:44     INFO - Setting pref dom.serviceWorkers.enabled to true
[task 2023-03-30T09:35:44.827Z] 09:35:44     INFO - Closing window 442a75c8-6f34-482d-9211-c3e7dd147f34
[task 2023-03-30T09:35:55.046Z] 09:35:55     INFO - 
[task 2023-03-30T09:35:55.046Z] 09:35:55     INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/data-transfer-files.https.html | Posting a File in a navigation handled by a service worker - Test timed out
[task 2023-03-30T09:35:55.077Z] 09:35:55     INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/data-transfer-files.https.html | expected OK
[task 2023-03-30T09:35:55.077Z] 09:35:55     INFO - TEST-INFO took 10278ms
[task 2023-03-30T09:35:55.079Z] 09:35:55     INFO - PID 6868 | 1680168955079	Marionette	INFO	Stopped listening on port 51061
[task 2023-03-30T09:35:55.093Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:35:55.100Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:35:55.101Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:35:55.102Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:35:55.103Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:35:55.104Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:35:55.108Z] 09:35:55     INFO - PID 6868 | [Child 9348, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:36:08.619Z] 09:36:08     INFO - PID 6868 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-03-30T09:36:08.626Z] 09:36:08     INFO - PID 6868 |           Blocker:  Waiting for ping task
[task 2023-03-30T09:36:08.626Z] 09:36:08     INFO - PID 6868 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-03-30T09:36:08.627Z] 09:36:08     INFO - PID 6868 |           State: (none)
[task 2023-03-30T09:36:08.628Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.628Z] 09:36:08     INFO - PID 6868 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-03-30T09:36:08.629Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-30T09:36:08.629Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-30T09:36:08.630Z] 09:36:08     INFO - PID 6868 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-30T09:36:08.631Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-30T09:36:08.631Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-30T09:36:08.632Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-30T09:36:08.632Z] 09:36:08     INFO - PID 6868 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-30T09:36:08.633Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-30T09:36:08.633Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-30T09:36:08.634Z] 09:36:08     INFO - PID 6868 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-30T09:36:08.634Z] 09:36:08     INFO - PID 6868 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-30T09:36:08.635Z] 09:36:08     INFO - PID 6868 | console.error: "TelemetryScheduler.shutdown - Already shut down"
[task 2023-03-30T09:36:08.635Z] 09:36:08     INFO - PID 6868 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-03-30T09:36:08.636Z] 09:36:08     INFO - PID 6868 |           Blocker:  Waiting for ping task
[task 2023-03-30T09:36:08.636Z] 09:36:08     INFO - PID 6868 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-03-30T09:36:08.637Z] 09:36:08     INFO - PID 6868 |           State: (none)
[task 2023-03-30T09:36:08.637Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.638Z] 09:36:08     INFO - PID 6868 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-03-30T09:36:08.639Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-30T09:36:08.640Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-30T09:36:08.640Z] 09:36:08     INFO - PID 6868 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-30T09:36:08.641Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-30T09:36:08.641Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-30T09:36:08.642Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-30T09:36:08.642Z] 09:36:08     INFO - PID 6868 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-30T09:36:08.643Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-30T09:36:08.643Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-30T09:36:08.644Z] 09:36:08     INFO - PID 6868 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-30T09:36:08.644Z] 09:36:08     INFO - PID 6868 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-30T09:36:08.645Z] 09:36:08     INFO - PID 6868 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-03-30T09:36:08.645Z] 09:36:08     INFO - PID 6868 |           Blocker:  TelemetryController: shutting down
[task 2023-03-30T09:36:08.646Z] 09:36:08     INFO - PID 6868 |           Phase: profile-before-change-telemetry
[task 2023-03-30T09:36:08.647Z] 09:36:08     INFO - PID 6868 |           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-03-30T09:36:08.648Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-30T09:36:08.648Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-30T09:36:08.649Z] 09:36:08     INFO - PID 6868 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-30T09:36:08.649Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-30T09:36:08.650Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-30T09:36:08.650Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-30T09:36:08.651Z] 09:36:08     INFO - PID 6868 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-30T09:36:08.651Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-30T09:36:08.652Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-30T09:36:08.652Z] 09:36:08     INFO - PID 6868 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-30T09:36:08.653Z] 09:36:08     INFO - PID 6868 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-30T09:36:08.653Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.654Z] 09:36:08     INFO - PID 6868 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-03-30T09:36:08.654Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-03-30T09:36:08.655Z] 09:36:08     INFO - PID 6868 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-03-30T09:36:08.655Z] 09:36:08     INFO - PID 6868 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-03-30T09:36:08.656Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-30T09:36:08.656Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-30T09:36:08.657Z] 09:36:08     INFO - PID 6868 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-30T09:36:08.657Z] 09:36:08     INFO - PID 6868 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-30T09:36:08.657Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-30T09:36:08.658Z] 09:36:08     INFO - PID 6868 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-30T09:36:08.658Z] 09:36:08     INFO - PID 6868 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-03-30T09:36:08.658Z] 09:36:08     INFO - PID 6868 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-30T09:36:08.729Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.743Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.744Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.745Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.746Z] 09:36:08     INFO - PID 6868 | 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-03-30T09:36:08.807Z] 09:36:08     INFO - Browser exited with return code 0
[task 2023-03-30T09:36:08.811Z] 09:36:08     INFO - Closing logging queue
[task 2023-03-30T09:36:08.811Z] 09:36:08     INFO - queue closed
[task 2023-03-30T09:36:08.980Z] 09:36:08     INFO - Application command: Z:\task_168016535516476\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_168016535516476\AppData\Local\Temp\tmp1jsnk3va
[task 2023-03-30T09:36:08.993Z] 09:36:08     INFO - PID 8444 | 1680168917210	Marionette	INFO	Marionette enabled
[task 2023-03-30T09:36:08.994Z] 09:36:08     INFO - PID 8444 | 1680168917214	Marionette	INFO	Listening on port 51129
[task 2023-03-30T09:36:08.995Z] 09:36:08     INFO - PID 8444 | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 58: Error: Can't find profile directory.
[task 2023-03-30T09:36:08.995Z] 09:36:08     INFO - PID 8444 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-03-30T09:36:08.996Z] 09:36:08     INFO - PID 8444 | [Child 3712, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:36:08.997Z] 09:36:08     INFO - PID 8444 | [Child 3712, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-03-30T09:36:08.998Z] 09:36:08     INFO - PID 8444 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_168016535516476\\AppData\\Local\\Temp\\tmpyzs7nd79\\search.json.mozlz4", (void 0)))
[task 2023-03-30T09:36:08.999Z] 09:36:08     INFO - PID 8444 | [ERROR glean_core] Error setting metrics feature config: Json(Error("EOF while parsing a value", line: 1, column: 0))
[task 2023-03-30T09:36:09.000Z] 09:36:08     INFO - PID 8444 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-03-30T09:36:09.000Z] 09:36:09     INFO - PID 8444 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-03-30T09:36:09.002Z] 09:36:09     INFO - PID 8444 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-03-30T09:36:09.002Z] 09:36:09     INFO - PID 8444 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
[task 2023-03-30T09:36:09.003Z] 09:36:09     INFO - Starting runner
[task 2023-03-30T09:36:10.014Z] 09:36:10     INFO - TEST-START | /service-workers/service-worker/dedicated-worker-service-worker-interception.https.html

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot 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.