Open Bug 1799998 Opened 2 years ago Updated 9 days ago

Intermittent /fetch/api/request/request-cache-force-cache.any.serviceworker.html | single tracking bug

Categories

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

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [necko-triaged])

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


[task 2022-11-09T20:51:42.598Z] 20:51:42     INFO - TEST-START | /fetch/api/request/request-cache-force-cache.any.serviceworker.html
[task 2022-11-09T20:51:42.599Z] 20:51:42     INFO - Closing window 00ed00d4-60f4-4e26-b850-1066f07df4cc
[task 2022-11-09T20:51:52.754Z] 20:51:52     INFO - TEST-UNEXPECTED-TIMEOUT | /fetch/api/request/request-cache-force-cache.any.serviceworker.html | expected OK
[task 2022-11-09T20:51:52.754Z] 20:51:52     INFO - TEST-INFO took 10161ms
[task 2022-11-09T20:51:52.762Z] 20:51:52     INFO - PID 7660 | 1668027112761	Marionette	INFO	Stopped listening on port 54173
[task 2022-11-09T20:51:57.410Z] 20:51:57     INFO - PID 7660 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-09T20:51:57.411Z] 20:51:57     INFO - PID 7660 |           Blocker:  Waiting for ping task
[task 2022-11-09T20:51:57.411Z] 20:51:57     INFO - PID 7660 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-09T20:51:57.412Z] 20:51:57     INFO - PID 7660 |           State: (none)
[task 2022-11-09T20:51:57.413Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.413Z] 20:51:57     INFO - PID 7660 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-09T20:51:57.414Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T20:51:57.414Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T20:51:57.415Z] 20:51:57     INFO - PID 7660 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T20:51:57.416Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T20:51:57.417Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T20:51:57.418Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T20:51:57.418Z] 20:51:57     INFO - PID 7660 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-09T20:51:57.419Z] 20:51:57     INFO - PID 7660 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-09T20:51:57.419Z] 20:51:57     INFO - PID 7660 | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:554:48
[task 2022-11-09T20:51:57.419Z] 20:51:57     INFO - PID 7660 | send@resource://gre/modules/TelemetryControllerParent.jsm:642:24
[task 2022-11-09T20:51:57.420Z] 20:51:57     INFO - PID 7660 | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-09T20:51:57.421Z] 20:51:57     INFO - PID 7660 | sendPing@resource://gre/modules/EventPing.jsm:51:30
[task 2022-11-09T20:51:57.421Z] 20:51:57     INFO - PID 7660 | _submitPing@resource://gre/modules/EventPing.jsm:229:12
[task 2022-11-09T20:51:57.422Z] 20:51:57     INFO - PID 7660 | shutdown@resource://gre/modules/EventPing.jsm:112:10
[task 2022-11-09T20:51:57.423Z] 20:51:57     INFO - PID 7660 | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:954:31
[task 2022-11-09T20:51:57.424Z] 20:51:57     INFO - PID 7660 | shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1024:24
[task 2022-11-09T20:51:57.424Z] 20:51:57     INFO - PID 7660 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T20:51:57.427Z] 20:51:57     INFO - PID 7660 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-09T20:51:57.427Z] 20:51:57     INFO - PID 7660 |           Blocker:  Waiting for ping task
[task 2022-11-09T20:51:57.428Z] 20:51:57     INFO - PID 7660 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-09T20:51:57.429Z] 20:51:57     INFO - PID 7660 |           State: (none)
[task 2022-11-09T20:51:57.430Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.431Z] 20:51:57     INFO - PID 7660 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-09T20:51:57.431Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T20:51:57.432Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T20:51:57.432Z] 20:51:57     INFO - PID 7660 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T20:51:57.433Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T20:51:57.434Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T20:51:57.434Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T20:51:57.435Z] 20:51:57     INFO - PID 7660 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-09T20:51:57.435Z] 20:51:57     INFO - PID 7660 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-09T20:51:57.436Z] 20:51:57     INFO - PID 7660 | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:554:48
[task 2022-11-09T20:51:57.437Z] 20:51:57     INFO - PID 7660 | send@resource://gre/modules/TelemetryControllerParent.jsm:642:24
[task 2022-11-09T20:51:57.437Z] 20:51:57     INFO - PID 7660 | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-09T20:51:57.438Z] 20:51:57     INFO - PID 7660 | saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:982:34
[task 2022-11-09T20:51:57.438Z] 20:51:57     INFO - PID 7660 | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
[task 2022-11-09T20:51:57.439Z] 20:51:57     INFO - PID 7660 | cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
[task 2022-11-09T20:51:57.439Z] 20:51:57     INFO - PID 7660 | shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
[task 2022-11-09T20:51:57.440Z] 20:51:57     INFO - PID 7660 | shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
[task 2022-11-09T20:51:57.441Z] 20:51:57     INFO - PID 7660 | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:973:35
[task 2022-11-09T20:51:57.442Z] 20:51:57     INFO - PID 7660 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T20:51:57.442Z] 20:51:57     INFO - PID 7660 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-09T20:51:57.443Z] 20:51:57     INFO - PID 7660 |           Blocker:  TelemetryController: shutting down
[task 2022-11-09T20:51:57.443Z] 20:51:57     INFO - PID 7660 |           Phase: profile-before-change-telemetry
[task 2022-11-09T20:51:57.444Z] 20:51:57     INFO - PID 7660 |           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-09T20:51:57.444Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T20:51:57.445Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T20:51:57.446Z] 20:51:57     INFO - PID 7660 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T20:51:57.446Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T20:51:57.447Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T20:51:57.447Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T20:51:57.448Z] 20:51:57     INFO - PID 7660 | getShutdownState@resource://gre/modules/TelemetrySend.jsm:1687:7
[task 2022-11-09T20:51:57.448Z] 20:51:57     INFO - PID 7660 | getShutdownState@resource://gre/modules/TelemetrySend.jsm:369:30
[task 2022-11-09T20:51:57.449Z] 20:51:57     INFO - PID 7660 | _getState@resource://gre/modules/TelemetryControllerParent.jsm:1072:38
[task 2022-11-09T20:51:57.449Z] 20:51:57     INFO - PID 7660 | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.jsm:931:18
[task 2022-11-09T20:51:57.450Z] 20:51:57     INFO - PID 7660 | safeGetState@resource://gre/modules/AsyncShutdown.jsm:242:17
[task 2022-11-09T20:51:57.450Z] 20:51:57     INFO - PID 7660 | Barrier/addBlocker/promise<@resource://gre/modules/AsyncShutdown.jsm:751:20
[task 2022-11-09T20:51:57.451Z] 20:51:57     INFO - PID 7660 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T20:51:57.452Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.452Z] 20:51:57     INFO - PID 7660 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-09T20:51:57.453Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T20:51:57.453Z] 20:51:57     INFO - PID 7660 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T20:51:57.454Z] 20:51:57     INFO - PID 7660 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T20:51:57.454Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T20:51:57.455Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T20:51:57.456Z] 20:51:57     INFO - PID 7660 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T20:51:57.457Z] 20:51:57     INFO - PID 7660 | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:735:5
[task 2022-11-09T20:51:57.457Z] 20:51:57     INFO - PID 7660 | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:249:17
[task 2022-11-09T20:51:57.458Z] 20:51:57     INFO - PID 7660 | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1235:42
[task 2022-11-09T20:51:57.458Z] 20:51:57     INFO - PID 7660 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T20:51:57.471Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.473Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.474Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.475Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.476Z] 20:51:57     INFO - PID 7660 | 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-09T20:51:57.534Z] 20:51:57     INFO - Browser exited with return code 0
[task 2022-11-09T20:51:57.539Z] 20:51:57     INFO - Closing logging queue
[task 2022-11-09T20:51:57.539Z] 20:51:57     INFO - queue closed
[task 2022-11-09T20:52:02.889Z] 20:52:02     INFO - Application command: Z:\task_166802603923340\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_166802603923340\AppData\Local\Temp\tmp5qaqpo7o
[task 2022-11-09T20:52:02.905Z] 20:52:02     INFO - PID 7516 | 1668027089006	Marionette	INFO	Marionette enabled
[task 2022-11-09T20:52:02.906Z] 20:52:02     INFO - PID 7516 | 1668027089009	Marionette	INFO	Listening on port 54228
[task 2022-11-09T20:52:02.907Z] 20:52:02     INFO - PID 7516 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_166802603923340\\AppData\\Local\\Temp\\tmpg5re9ga8\\search.json.mozlz4", (void 0)))
[task 2022-11-09T20:52:02.908Z] 20:52:02     INFO - PID 7516 | *** You are running in background task mode. ***
[task 2022-11-09T20:52:02.908Z] 20:52:02     INFO - PID 7516 | *** You are running in headless mode.
[task 2022-11-09T20:52:02.909Z] 20:52:02     INFO - PID 7516 | console.error: "C:\\Users\\task_166802603923340\\AppData\\Local\\Temp\\tmpg5re9ga8" "" 0 ".purge.bg_rm"
[task 2022-11-09T20:52:02.910Z] 20:52:02     INFO - Starting runner
[task 2022-11-09T20:52:04.122Z] 20:52:04     INFO - TEST-START | /fetch/api/request/request-cache-no-cache.any.html
Duplicate of this bug: 1752067
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → NEW
You need to log in before you can comment on or make changes to this bug.