Closed Bug 1810828 Opened 1 year ago Closed 1 year ago

High freq /FileAPI/url/url-with-fetch.any.worker.html | single tracking bug

Categories

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

defect

Tracking

()

RESOLVED FIXED
111 Branch
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

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.

Summary: Intermittent /FileAPI/url/url-with-fetch.any.worker.html | single tracking bug → High freq /FileAPI/url/url-with-fetch.any.worker.html | single tracking bug

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.

Flags: needinfo?(echuang)
Flags: needinfo?(echuang)

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.

Flags: needinfo?(echuang)

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: nobody → echuang
Status: NEW → ASSIGNED
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
Blocks: 1812039
Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → 111 Branch
You need to log in before you can comment on or make changes to this bug.