1827409 - Intermittent /fetch/api/response/response-stream-disturbed-by-pipe.any.serviceworker.html | single tracking bug

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

ask 2023-04-11T12:32:46.896Z] 12:32:46     INFO - TEST-START | /fetch/api/response/response-stream-disturbed-by-pipe.any.serviceworker.html
[task 2023-04-11T12:32:46.899Z] 12:32:46     INFO - Closing window 102bc6eb-f1f4-4f8f-9490-f26b202e601e
[task 2023-04-11T12:33:07.204Z] 12:33:07     INFO - TEST-UNEXPECTED-TIMEOUT | /fetch/api/response/response-stream-disturbed-by-pipe.any.serviceworker.html | expected OK
[task 2023-04-11T12:33:07.204Z] 12:33:07     INFO - TEST-INFO took 20324ms
[task 2023-04-11T12:33:07.211Z] 12:33:07     INFO - PID 10224 | 1681216387210	Marionette	INFO	Stopped listening on port 59847
[task 2023-04-11T12:33:07.236Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:07.238Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:07.240Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:07.243Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:07.244Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:07.245Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:07.249Z] 12:33:07     INFO - PID 10224 | [Child 3892, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:22.992Z] 12:33:22     INFO - PID 10224 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.sys.mjs", 370))
[task 2023-04-11T12:33:22.996Z] 12:33:22     INFO - PID 10224 | JavaScript error: resource:///modules/WindowsJumpLists.jsm, line 270: TypeError: can't access property "addListToBuild", this._builder is undefined
[task 2023-04-11T12:33:22.997Z] 12:33:22     INFO - PID 10224 | JavaScript error: resource:///modules/WindowsJumpLists.jsm, line 270: TypeError: can't access property "addListToBuild", this._builder is undefined
[task 2023-04-11T12:33:33.003Z] 12:33:33     INFO - PID 10224 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Places Connection shutdown","state":{"PlacesShutdownProgress":5},"filename":"Z:/task_168120345170421/build/src/toolkit/components/places/Database.cpp","lineNumber":470,"stack":""}] Barrier: profile-before-change
[task 2023-04-11T12:33:43.016Z] 12:33:43     INFO - PID 10224 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-11T12:33:43.016Z] 12:33:43     INFO - PID 10224 |           Blocker:  Waiting for ping task
[task 2023-04-11T12:33:43.017Z] 12:33:43     INFO - PID 10224 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-04-11T12:33:43.018Z] 12:33:43     INFO - PID 10224 |           State: (none)
[task 2023-04-11T12:33:43.018Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.019Z] 12:33:43     INFO - PID 10224 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-11T12:33:43.020Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-11T12:33:43.020Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-11T12:33:43.021Z] 12:33:43     INFO - PID 10224 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-11T12:33:43.022Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-11T12:33:43.022Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-11T12:33:43.023Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-11T12:33:43.023Z] 12:33:43     INFO - PID 10224 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-11T12:33:43.023Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-11T12:33:43.024Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-11T12:33:43.024Z] 12:33:43     INFO - PID 10224 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-11T12:33:43.025Z] 12:33:43     INFO - PID 10224 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-11T12:33:43.025Z] 12:33:43     INFO - PID 10224 | console.error: "TelemetryScheduler.shutdown - Already shut down"
[task 2023-04-11T12:33:43.036Z] 12:33:43     INFO - PID 10224 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-11T12:33:43.036Z] 12:33:43     INFO - PID 10224 |           Blocker:  Waiting for ping task
[task 2023-04-11T12:33:43.037Z] 12:33:43     INFO - PID 10224 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-04-11T12:33:43.037Z] 12:33:43     INFO - PID 10224 |           State: (none)
[task 2023-04-11T12:33:43.039Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.039Z] 12:33:43     INFO - PID 10224 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-11T12:33:43.040Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-11T12:33:43.040Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-11T12:33:43.041Z] 12:33:43     INFO - PID 10224 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-11T12:33:43.041Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-11T12:33:43.042Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-11T12:33:43.042Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-11T12:33:43.043Z] 12:33:43     INFO - PID 10224 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-11T12:33:43.044Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-11T12:33:43.044Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-11T12:33:43.045Z] 12:33:43     INFO - PID 10224 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-11T12:33:43.045Z] 12:33:43     INFO - PID 10224 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-11T12:33:43.046Z] 12:33:43     INFO - PID 10224 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-11T12:33:43.048Z] 12:33:43     INFO - PID 10224 |           Blocker:  TelemetryController: shutting down
[task 2023-04-11T12:33:43.048Z] 12:33:43     INFO - PID 10224 |           Phase: profile-before-change-telemetry
[task 2023-04-11T12:33:43.049Z] 12:33:43     INFO - PID 10224 |           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-04-11T12:33:43.050Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-11T12:33:43.050Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-11T12:33:43.051Z] 12:33:43     INFO - PID 10224 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-11T12:33:43.051Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-11T12:33:43.052Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-11T12:33:43.053Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-11T12:33:43.053Z] 12:33:43     INFO - PID 10224 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-11T12:33:43.054Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-11T12:33:43.054Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-11T12:33:43.055Z] 12:33:43     INFO - PID 10224 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-11T12:33:43.056Z] 12:33:43     INFO - PID 10224 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-11T12:33:43.057Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.057Z] 12:33:43     INFO - PID 10224 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-11T12:33:43.058Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-11T12:33:43.058Z] 12:33:43     INFO - PID 10224 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-11T12:33:43.059Z] 12:33:43     INFO - PID 10224 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-11T12:33:43.059Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-11T12:33:43.060Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-11T12:33:43.060Z] 12:33:43     INFO - PID 10224 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-11T12:33:43.061Z] 12:33:43     INFO - PID 10224 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-11T12:33:43.061Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-11T12:33:43.062Z] 12:33:43     INFO - PID 10224 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-11T12:33:43.062Z] 12:33:43     INFO - PID 10224 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-11T12:33:43.063Z] 12:33:43     INFO - PID 10224 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-11T12:33:43.078Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.082Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.083Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.084Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.085Z] 12:33:43     INFO - PID 10224 | 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-04-11T12:33:43.815Z] 12:33:43     INFO - PID 10224 | [Parent 7016, IPC I/O Parent] WARNING: Process 5988 may be hanging at shutdown; will wait for up to 80000ms: file Z:/task_168120345170421/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-11T12:33:44.616Z] 12:33:44     INFO - PID 10224 | [Parent 7016, IPC I/O Parent] WARNING: Process 5048 may be hanging at shutdown; will wait for up to 79203ms: file Z:/task_168120345170421/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-11T12:33:47.660Z] 12:33:47     INFO - Browser exited with return code 0
[task 2023-04-11T12:33:47.664Z] 12:33:47     INFO - Closing logging queue
[task 2023-04-11T12:33:47.664Z] 12:33:47     INFO - queue closed
[task 2023-04-11T12:33:47.864Z] 12:33:47     INFO - Application command: Z:\task_168121363713853\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_168121363713853\AppData\Local\Temp\tmp6zljdsfp
[task 2023-04-11T12:33:47.874Z] 12:33:47     INFO - PID 7932 | 1681216286386	Marionette	INFO	Marionette enabled
[task 2023-04-11T12:33:47.875Z] 12:33:47     INFO - PID 7932 | 1681216286392	Marionette	INFO	Listening on port 59862
[task 2023-04-11T12:33:47.876Z] 12:33:47     INFO - PID 7932 | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 58: Error: Can't find profile directory.
[task 2023-04-11T12:33:47.877Z] 12:33:47     INFO - PID 7932 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-11T12:33:47.878Z] 12:33:47     INFO - PID 7932 | [Child 8656, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:47.879Z] 12:33:47     INFO - PID 7932 | [Child 8656, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168120345170421/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-11T12:33:47.880Z] 12:33:47     INFO - PID 7932 | [ERROR glean_core] Error setting metrics feature config: Json(Error("EOF while parsing a value", line: 1, column: 0))
[task 2023-04-11T12:33:47.881Z] 12:33:47     INFO - PID 7932 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-11T12:33:47.882Z] 12:33:47     INFO - PID 7932 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-11T12:33:47.883Z] 12:33:47     INFO - PID 7932 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-11T12:33:47.884Z] 12:33:47     INFO - PID 7932 | 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-04-11T12:33:47.884Z] 12:33:47     INFO - Starting runner

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1827409&startday=2023-04-10&endday=2023-04-16&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1827409&startday=2023-05-15&endday=2023-05-21&tree=all

Comment 3

[BugBot [:suhaib / :marco]]

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