Intermittent /resource-timing/resource_timing.worker.html | single tracking bug
Categories
(Core :: DOM: Workers, defect, P2)
Tracking
()
| Tracking | Status | |
|---|---|---|
| firefox-esr102 | --- | unaffected |
| firefox109 | --- | unaffected |
| firefox110 | --- | unaffected |
| firefox111 | --- | disabled |
| firefox112 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: edenchuang)
References
(Regression)
Details
(Keywords: intermittent-failure, intermittent-testcase, regression)
Attachments
(4 files)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=402672885&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YlgxrvyOReKb5jIc14DDDw/runs/0/artifacts/public/logs/live_backing.log
[task 2023-01-17T18:05:49.928Z] 18:05:49 INFO - TEST-START | /resource-timing/resource_timing.worker.html
[task 2023-01-17T18:05:49.945Z] 18:05:49 INFO - Closing window 61a5d3d6-7262-4876-bc30-c0181013e9fc
[task 2023-01-17T18:05:50.223Z] 18:05:50 INFO - PID 5140 | JavaScript error: , line 0: uncaught exception: Object
[task 2023-01-17T18:06:00.167Z] 18:06:00 INFO -
[task 2023-01-17T18:06:00.167Z] 18:06:00 INFO - TEST-UNEXPECTED-TIMEOUT | /resource-timing/resource_timing.worker.html | Performance Resource Entries in workers - Test timed out
[task 2023-01-17T18:06:00.168Z] 18:06:00 INFO - TEST-UNEXPECTED-TIMEOUT | /resource-timing/resource_timing.worker.html | expected OK
[task 2023-01-17T18:06:00.168Z] 18:06:00 INFO - TEST-INFO took 10240ms
[task 2023-01-17T18:06:00.169Z] 18:06:00 INFO - PID 5140 | 1673978760167 Marionette INFO Stopped listening on port 40253
[task 2023-01-17T18:06:00.422Z] 18:06:00 INFO - PID 5140 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-17T18:06:00.423Z] 18:06:00 INFO - PID 5140 | Blocker: Waiting for ping task
[task 2023-01-17T18:06:00.423Z] 18:06:00 INFO - PID 5140 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-17T18:06:00.424Z] 18:06:00 INFO - PID 5140 | State: (none)
[task 2023-01-17T18:06:00.429Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.429Z] 18:06:00 INFO - PID 5140 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-17T18:06:00.430Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T18:06:00.430Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T18:06:00.431Z] 18:06:00 INFO - PID 5140 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T18:06:00.431Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T18:06:00.431Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T18:06:00.431Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T18:06:00.431Z] 18:06:00 INFO - PID 5140 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T18:06:00.431Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T18:06:00.432Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T18:06:00.432Z] 18:06:00 INFO - PID 5140 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T18:06:00.433Z] 18:06:00 INFO - PID 5140 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T18:06:00.438Z] 18:06:00 INFO - PID 5140 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-17T18:06:00.439Z] 18:06:00 INFO - PID 5140 | Blocker: Waiting for ping task
[task 2023-01-17T18:06:00.440Z] 18:06:00 INFO - PID 5140 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-17T18:06:00.441Z] 18:06:00 INFO - PID 5140 | State: (none)
[task 2023-01-17T18:06:00.442Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.444Z] 18:06:00 INFO - PID 5140 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-17T18:06:00.445Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T18:06:00.448Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T18:06:00.449Z] 18:06:00 INFO - PID 5140 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T18:06:00.450Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T18:06:00.450Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T18:06:00.450Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T18:06:00.452Z] 18:06:00 INFO - PID 5140 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T18:06:00.452Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T18:06:00.452Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T18:06:00.452Z] 18:06:00 INFO - PID 5140 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T18:06:00.453Z] 18:06:00 INFO - PID 5140 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T18:06:00.454Z] 18:06:00 INFO - PID 5140 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-17T18:06:00.455Z] 18:06:00 INFO - PID 5140 | Blocker: TelemetryController: shutting down
[task 2023-01-17T18:06:00.456Z] 18:06:00 INFO - PID 5140 | Phase: profile-before-change-telemetry
[task 2023-01-17T18:06:00.457Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.458Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T18:06:00.459Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T18:06:00.459Z] 18:06:00 INFO - PID 5140 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T18:06:00.460Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T18:06:00.460Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T18:06:00.461Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T18:06:00.461Z] 18:06:00 INFO - PID 5140 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T18:06:00.462Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T18:06:00.462Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T18:06:00.463Z] 18:06:00 INFO - PID 5140 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T18:06:00.464Z] 18:06:00 INFO - PID 5140 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T18:06:00.464Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.465Z] 18:06:00 INFO - PID 5140 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-17T18:06:00.466Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T18:06:00.466Z] 18:06:00 INFO - PID 5140 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T18:06:00.467Z] 18:06:00 INFO - PID 5140 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T18:06:00.467Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T18:06:00.468Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T18:06:00.468Z] 18:06:00 INFO - PID 5140 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T18:06:00.469Z] 18:06:00 INFO - PID 5140 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T18:06:00.470Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T18:06:00.470Z] 18:06:00 INFO - PID 5140 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T18:06:00.471Z] 18:06:00 INFO - PID 5140 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T18:06:00.471Z] 18:06:00 INFO - PID 5140 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T18:06:00.472Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.473Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.473Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.474Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.475Z] 18:06:00 INFO - PID 5140 | 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-01-17T18:06:00.666Z] 18:06:00 INFO - Browser exited with return code 0
[task 2023-01-17T18:06:00.669Z] 18:06:00 INFO - Closing logging queue
[task 2023-01-17T18:06:00.670Z] 18:06:00 INFO - queue closed
[task 2023-01-17T18:06:00.712Z] 18:06:00 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmp3_hw6pwt
[task 2023-01-17T18:06:00.732Z] 18:06:00 INFO - PID 9466 | 1673978670735 Marionette INFO Marionette enabled
[task 2023-01-17T18:06:00.733Z] 18:06:00 INFO - PID 9466 | 1673978670738 Marionette INFO Listening on port 53425
[task 2023-01-17T18:06:00.733Z] 18:06:00 INFO - PID 9466 | console.error: ({})
[task 2023-01-17T18:06:00.734Z] 18:06:00 INFO - PID 9466 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpqp513z2i/search.json.mozlz4", (void 0)))
[task 2023-01-17T18:06:00.734Z] 18:06:00 INFO - PID 9466 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T18:06:00.735Z] 18:06:00 INFO - PID 9466 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T18:06:00.740Z] 18:06:00 INFO - PID 9466 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T18:06:00.741Z] 18:06:00 INFO - PID 9466 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T18:06:00.741Z] 18:06:00 INFO - PID 9466 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2023-01-17T18:06:00.741Z] 18:06:00 INFO - Starting runner
[task 2023-01-17T18:06:01.524Z] 18:06:01 INFO - TEST-START | /resource-timing/resource_timing_content_length.html
Comment 1•3 years ago
|
||
Context here: https://bugzilla.mozilla.org/show_bug.cgi?id=1351231#c28.
Comment 2•3 years ago
|
||
Set release status flags based on info from the regressing bug 1351231
:edenchuang, since you are the author of the regressor, bug 1351231, could you take a look?
For more information, please visit auto_nag documentation.
| Comment hidden (Intermittent Failures Robot) |
| Assignee | ||
Comment 4•3 years ago
|
||
After PFetch is enabled. ResourceTiming saving point is different from without PFetch.
Initially, Saving ResourceTiming is triggered by HttpChannelChild::OnStopRequest, then eventually, WorkerFetchResolver::OnResponseEnd is called to complete the resource fetching. There is a time difference between these two methods, so ResourceTiming would be ready when response.text() or response.blob() is called.
When PFetch is enabled, there is no actual channel in the content process. ResourceTiming saving point is moved to FetchChild::RecvOnResponseEnd(), which means there would be no time difference anymore between these methods. And the race appears between response.text()/response.blob() and ResourceTiming saving. And this is why we meet this intermittent failure.
I am working on a patch to resolve the race.
| Assignee | ||
Updated•3 years ago
|
| Assignee | ||
Comment 5•3 years ago
|
||
| Assignee | ||
Comment 6•3 years ago
|
||
Depends on D167936
| Assignee | ||
Comment 7•3 years ago
|
||
Depends on D167937
| Assignee | ||
Comment 8•3 years ago
|
||
Depends on D167938
Updated•3 years ago
|
Updated•3 years ago
|
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
Comment 13•3 years ago
|
||
There have been 61 total failures in the last 7 days.
Affected platforms are:
- 1 failure on
linux1804-32-shippable-qr - 6 failures on ```linux1804-64-asan-qr``
- 2 failures on
linux1804-64-ccov-qr - 31 failures on
linux1804-64-qr - 11 failures on
linux1804-64-shippable-qr - 1 failure on
macosx1015-64-qr - 9 failures on
windows10-32-2004-qr
Recent failure log.
Updated•3 years ago
|
| Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
| Comment hidden (Intermittent Failures Robot) |
Comment 16•3 years ago
|
||
Comment 17•3 years ago
|
||
Backed out for causing high failure rate on /service-workers/service-worker/navigation-headers.https.html (based on failures per number of runs)
- backout: https://hg.mozilla.org/integration/autoland/rev/5fddaccf933d89f1b36bde8fba6873d0dc88a9f8
- push: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&revision=2479dc7989945cd526a3c4c6ef7d6210d437eeb1
- failure log: https://treeherder.mozilla.org/logviewer?job_id=406560900&repo=autoland&lineNumber=30906
- failure snippet:
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO - TEST-PASS | /service-workers/service-worker/navigation-headers.https.html | POST Navigation, same-origin with fallback service worker sets correct origin and referer headers.
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/navigation-headers.https.html | GET Navigation, same-origin with navpreload service worker sets correct origin and referer headers. - Test timed out
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO -
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/navigation-headers.https.html | GET Navigation, same-origin with service worker that changes the request sets correct origin and referer headers. - expected PASS
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO -
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/navigation-headers.https.html | POST Navigation, same-origin with service worker that changes the request sets correct origin and referer headers. - expected PASS
[task 2023-02-22T19:34:13.524Z] 19:34:13 INFO -
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/navigation-headers.https.html | GET Navigation, same-site with no service worker sets correct origin and referer headers. - expected PASS
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO -
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/navigation-headers.https.html | POST Navigation, same-site with no service worker sets correct origin and referer headers. - expected PASS
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO -
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/navigation-headers.https.html | GET Navigation, same-site with passthrough service worker sets correct origin and referer headers. - expected PASS
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO -
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO - TEST-UNEXPECTED-NOTRUN | /service-workers/service-worker/navigation-headers.https.html | POST Navigation, same-site with passthrough service worker sets correct origin and referer headers. - expected FAIL
[task 2023-02-22T19:34:13.525Z] 19:34:13 INFO - TEST-INFO | expected FAIL
Comment 18•3 years ago
|
||
| Assignee | ||
Updated•3 years ago
|
Comment 19•3 years ago
|
||
| bugherder | ||
https://hg.mozilla.org/mozilla-central/rev/1f5e8fd35737
https://hg.mozilla.org/mozilla-central/rev/2051ecee5fb9
https://hg.mozilla.org/mozilla-central/rev/819715a61b4b
https://hg.mozilla.org/mozilla-central/rev/84da76cce01c
| Comment hidden (Intermittent Failures Robot) |
Description
•