High freq /FileAPI/url/url-with-fetch.any.worker.html | single tracking bug
Categories
(Core :: DOM: File, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox-esr102 | --- | unaffected |
firefox109 | --- | unaffected |
firefox110 | --- | unaffected |
firefox111 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: edenchuang)
References
(Regression)
Details
(Keywords: intermittent-failure, intermittent-testcase, regression)
Attachments
(1 file)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=402667737&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SUHZ6uWISsicYv0ioArhNQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-01-17T17:20:43.835Z] 17:20:43 INFO - TEST-START | /FileAPI/url/url-with-fetch.any.worker.html
[task 2023-01-17T17:20:43.835Z] 17:20:43 INFO - Closing window 0579b79b-b8c7-4c0b-a1f9-097e87e513a9
[task 2023-01-17T17:20:44.052Z] 17:20:44 INFO - .....
[task 2023-01-17T17:20:44.052Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | Appending a path should cause fetch to fail
[task 2023-01-17T17:20:44.052Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch with method "HEAD" should fail
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch with method "POST" should fail
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch with method "DELETE" should fail
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch with method "OPTIONS" should fail
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch with method "PUT" should fail
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch with method "CUSTOM" should fail
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-PASS | /FileAPI/url/url-with-fetch.any.worker.html | fetch should return Content-Type from Blob
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-FAIL | /FileAPI/url/url-with-fetch.any.worker.html | Revoke blob URL after creating Request, will fetch - promise_test: Unhandled rejection with value: object "TypeError: NetworkError when attempting to fetch resource."
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-FAIL | /FileAPI/url/url-with-fetch.any.worker.html | Revoke blob URL after creating Request, then clone Request, will fetch - promise_test: Unhandled rejection with value: object "TypeError: NetworkError when attempting to fetch resource."
[task 2023-01-17T17:20:44.056Z] 17:20:44 INFO - TEST-UNEXPECTED-FAIL | /FileAPI/url/url-with-fetch.any.worker.html | Revoke blob URL after calling fetch, fetch should succeed - promise_test: Unhandled rejection with value: object "TypeError: NetworkError when attempting to fetch resource."
[task 2023-01-17T17:20:44.057Z] 17:20:44 INFO - TEST-OK | /FileAPI/url/url-with-fetch.any.worker.html | took 216ms
[task 2023-01-17T17:20:44.059Z] 17:20:44 INFO - PID 996 | 1673976044051 Marionette INFO Stopped listening on port 49876
[task 2023-01-17T17:20:44.438Z] 17:20:44 INFO - PID 996 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-17T17:20:44.446Z] 17:20:44 INFO - PID 996 | Blocker: Waiting for ping task
[task 2023-01-17T17:20:44.446Z] 17:20:44 INFO - PID 996 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-17T17:20:44.447Z] 17:20:44 INFO - PID 996 | State: (none)
[task 2023-01-17T17:20:44.448Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.449Z] 17:20:44 INFO - PID 996 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-17T17:20:44.449Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T17:20:44.450Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T17:20:44.451Z] 17:20:44 INFO - PID 996 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T17:20:44.451Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T17:20:44.451Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T17:20:44.452Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T17:20:44.453Z] 17:20:44 INFO - PID 996 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T17:20:44.453Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T17:20:44.454Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T17:20:44.455Z] 17:20:44 INFO - PID 996 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T17:20:44.456Z] 17:20:44 INFO - PID 996 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T17:20:44.456Z] 17:20:44 INFO - PID 996 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-17T17:20:44.457Z] 17:20:44 INFO - PID 996 | Blocker: Waiting for ping task
[task 2023-01-17T17:20:44.457Z] 17:20:44 INFO - PID 996 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-17T17:20:44.458Z] 17:20:44 INFO - PID 996 | State: (none)
[task 2023-01-17T17:20:44.459Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.459Z] 17:20:44 INFO - PID 996 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-17T17:20:44.460Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T17:20:44.461Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T17:20:44.461Z] 17:20:44 INFO - PID 996 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T17:20:44.462Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T17:20:44.463Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T17:20:44.464Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T17:20:44.464Z] 17:20:44 INFO - PID 996 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T17:20:44.465Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T17:20:44.465Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T17:20:44.466Z] 17:20:44 INFO - PID 996 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T17:20:44.467Z] 17:20:44 INFO - PID 996 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T17:20:44.467Z] 17:20:44 INFO - PID 996 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-17T17:20:44.468Z] 17:20:44 INFO - PID 996 | Blocker: TelemetryController: shutting down
[task 2023-01-17T17:20:44.468Z] 17:20:44 INFO - PID 996 | Phase: profile-before-change-telemetry
[task 2023-01-17T17:20:44.469Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.470Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T17:20:44.470Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T17:20:44.471Z] 17:20:44 INFO - PID 996 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T17:20:44.472Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T17:20:44.472Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T17:20:44.473Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T17:20:44.473Z] 17:20:44 INFO - PID 996 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T17:20:44.473Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T17:20:44.474Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T17:20:44.474Z] 17:20:44 INFO - PID 996 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T17:20:44.475Z] 17:20:44 INFO - PID 996 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T17:20:44.476Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.476Z] 17:20:44 INFO - PID 996 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-17T17:20:44.477Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-17T17:20:44.477Z] 17:20:44 INFO - PID 996 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-17T17:20:44.478Z] 17:20:44 INFO - PID 996 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-17T17:20:44.478Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-17T17:20:44.479Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-17T17:20:44.480Z] 17:20:44 INFO - PID 996 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-17T17:20:44.481Z] 17:20:44 INFO - PID 996 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-17T17:20:44.481Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-17T17:20:44.481Z] 17:20:44 INFO - PID 996 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-17T17:20:44.482Z] 17:20:44 INFO - PID 996 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-17T17:20:44.482Z] 17:20:44 INFO - PID 996 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-17T17:20:44.485Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.489Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.490Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.491Z] 17:20:44 INFO - PID 996 | 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-17T17:20:44.492Z] 17:20:44 INFO - PID 996 | 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-17T17:20:45.054Z] 17:20:45 INFO - Browser exited with return code 0
[task 2023-01-17T17:20:45.058Z] 17:20:45 INFO - Closing logging queue
[task 2023-01-17T17:20:45.058Z] 17:20:45 INFO - queue closed
[task 2023-01-17T17:20:45.108Z] 17:20:45 INFO - Application command: Z:\task_167397491089317\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_167397491089317\AppData\Local\Temp\tmpak397oa5
[task 2023-01-17T17:20:45.113Z] 17:20:45 INFO - PID 7152 | 1673976034717 Marionette INFO Marionette enabled
[task 2023-01-17T17:20:45.114Z] 17:20:45 INFO - PID 7152 | 1673976034721 Marionette INFO Listening on port 49877
[task 2023-01-17T17:20:45.115Z] 17:20:45 INFO - PID 7152 | console.error: "Warning: unrecognized command line flag -wait-for-browser\n"
[task 2023-01-17T17:20:45.116Z] 17:20:45 INFO - PID 7152 | JavaScript error: resource://gre/modules/XULStore.jsm, line 58: Error: Can't find profile directory.
[task 2023-01-17T17:20:45.117Z] 17:20:45 INFO - PID 7152 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T17:20:45.118Z] 17:20:45 INFO - PID 7152 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_167397491089317\\AppData\\Local\\Temp\\tmpzf1pe564\\search.json.mozlz4", (void 0)))
[task 2023-01-17T17:20:45.119Z] 17:20:45 INFO - PID 7152 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T17:20:45.119Z] 17:20:45 INFO - PID 7152 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T17:20:45.120Z] 17:20:45 INFO - PID 7152 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-17T17:20:45.120Z] 17:20:45 INFO - Starting runner
[task 2023-01-17T17:20:46.113Z] 17:20:46 INFO - TEST-START | /FileAPI/url/url-with-xhr.any.worker.html
Comment 1•4 months ago
|
||
Context here: https://bugzilla.mozilla.org/show_bug.cgi?id=1351231#c28.
Comment 2•4 months 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) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 months ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 6•4 months ago
|
||
From the error message
[task 2023-01-23T21:25:36.312Z] 21:25:36 INFO - TEST-FAIL | /FileAPI/url/url-with-fetch.any.worker.html | Revoke blob URL after creating Request, will fetch - promise_test: Unhandled rejection with value: object "TypeError: NetworkError when attempting to fetch resource."
[task 2023-01-23T21:25:36.312Z] 21:25:36 INFO - TEST-FAIL | /FileAPI/url/url-with-fetch.any.worker.html | Revoke blob URL after creating Request, then clone Request, will fetch - promise_test: Unhandled rejection with value: object "TypeError: NetworkError when attempting to fetch resource."
it seems, we get a MSG_FETCH_FAILED
probably from the WorkerFetchResponseRunnable
.
The only place we set mInternalResponse->Type()
to ResponseType::Error
seems to be InternalResponse::NetworkError
. That gets called by quite some pathes, unfortunately.
A first step forward might be to add some (nightly) logging that prints out the original error code we are dropping on the floor to see if we can narrow down the possible code paths.
Updated•4 months ago
|
Assignee | ||
Comment 7•4 months ago
|
||
Root cause analysis
A race between Fetch and object URL revoking is introduced by PFetch.
Originally, Fetch on worker and object URL revoking are scheduled on the content process main thread. Their execution sequence ensures there would not have a race condition because their thread/process execution flow is the same.
Worker thread -> content process(main thread) -> parent process (main thread)
So object URL revoking would not be executed before fetch checking(MayLoad checking in nsScriptSecurityManager).
However, after PFetch is enabled, the fetch thread/process is changed to
Worker thread -> parent process (background thread) -> parent process (main thread)
Therefore, we can not ensure which one, fetch or object URL revoking, will be in the parent process main thread first. If the object URL revoking is fast. It would make the fetch checking fail since the corresponding information is gone with revoking.
Worker around and solution
Here we have some known fails with object URL revoking
https://searchfox.org/mozilla-central/rev/cf3af6bb6657278880f8baf38435eeb8f2d5d86c/testing/web-platform/meta/FileAPI/url/url-with-fetch.any.js.ini
And after taking a look at these issues, I found they all related to object URL revoking when using. And they can be fixed together by some flags for synchronization. So here I want to update the expected test result for PFetch to OK/FAIL first. Then giving the total solution for these three tests.
Assignee | ||
Comment 8•4 months ago
|
||
Root cause analysis:
A race between Fetch and object URL revoking is introduced by PFetch.
Originally, Fetch on worker and object URL revoking are scheduled on the content process main thread. Their execution sequence ensures there would not have a race condition because their thread/process execution flow is the same.
Worker thread -> content process(main thread) -> parent process (main thread)
So object URL revoking would not be executed before fetch checking(MayLoad checking in nsScriptSecurityManager).
However, after PFetch is enabled, the fetch thread/process is changed to
Worker thread -> parent process (background thread) -> parent process (main thread)
Therefore, we can not ensure which one, fetch or object URL revoking, will be in the parent process main thread first. If the object URL revoking is fast. It would make the fetch checking fail since the corresponding information is gone with revoking.
Worker around and solution:
Here we have some known fails with object URL revoking
https://searchfox.org/mozilla-central/rev/cf3af6bb6657278880f8baf38435eeb8f2d5d86c/testing/web-platform/meta/FileAPI/url/url-with-fetch.any.js.ini
And after taking a look at these issues, I found they all related to object URL revoking when using. And they can be fixed together by some flags for synchronization. So here I want to update the expected test result for PFetch to OK/FAIL first. Then giving the total solution for these three tests.
Updated•4 months ago
|
Pushed by echuang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/8ae6f5b2a0a1 Update the expected result of FileAPI/url/url-with-fetch.any.js to reduce a known issue of PFetch. r=dom-worker-reviewers,jstutte
Comment hidden (Intermittent Failures Robot) |
Comment 11•4 months ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Description
•