downloads.removeFile fails with "file doesn't exist" occasionally
Categories
(WebExtensions :: General, defect, P3)
Tracking
(firefox108 wontfix, firefox109 wontfix, firefox110 wontfix, firefox111 wontfix, firefox112 verified)
People
(Reporter: danny0838, Assigned: robwu)
References
Details
(Whiteboard: [addons-jira])
Attachments
(5 files, 1 obsolete file)
User Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0
Steps to reproduce:
- Download the test extension and install it.
- The extension will automatically perform tests for a path under the default download directory.
- Open the inspector for the background page of the extension and keep watching.
Actual results:
The test fails with an error like:
Error: Failed to download "test-downloads-removefile/mypath(####)": Could not remove download id #### because the file doesn't exist
after several (around hundreds to thousands) loops, with the test file at "test-downloads-removefile/mypath(####)" with content still exists.
Expected results:
downloads.removeFile("test-downloads-removefile/mypath(####)") in the test should never fail with reason "file doesn't exist" as the file to remove actually exists.
Comment 2•2 years ago
|
||
The Bugbug bot thinks this bug should belong to the 'Firefox::Downloads Panel' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.
Comment 3•2 years ago
|
||
The error comes from webextensions code - https://searchfox.org/mozilla-central/rev/d6a131ceb435c03ccab2592578f6e2ebf12c1644/toolkit/components/extensions/parent/ext-downloads.js#1057-1063 which is explicitly doing the file removal itself and asking for it not to ignore files that are already gone... and then also assumes that any error means the file doesn't exist (when there could also be other reasons the file removal fails).
Over to the webextensions team for further triage.
Comment 4•2 years ago
|
||
Hello,
I reproduced the issue on the latest Nightly (110.0a1/20230105213109), Beta (109.0b9/20230105190654) and Release (108.0.2/20230104165113) under Windows 10 x64 and Ubuntu 16.04 LTS.
Immediately after loading the extension, a file is downloaded and checking the extension console reveals the mentioned error. Checking the download location shows the file is still there. It wasn’t removed and still exists.
For further details, see the attached screenshot.
Comment 5•2 years ago
|
||
Assignee | ||
Comment 6•2 years ago
|
||
To investigate. The very least that we should do is to account for more errors besides just a missing file.
E.g. on Windows, there are occasionally errors related to file locking. On all platforms, the file can also fail to be removed due to permission changes.
In this specific case, because the issue has been verified to be happening on Windows and Linux, I suspect that the error message may be accurate, i.e. that the file is somehow missing when the download is reported to be completed.
Updated•2 years ago
|
Assignee | ||
Comment 7•2 years ago
|
||
I reproduced the issue. The specific windows error is 32 aka ERROR_SHARING_VIOLATION, "The process cannot access the file because it is being used by another process." . I imagine this to happen if another program (e.g. antivirus) tried to scan the file and kept the file locked because of that.
To make this more obvious, I'm going to make the error message more accurate: to only report the (common) file not found error if it is really that error, and dump a useful message to the console otherwise.
Assignee | ||
Comment 8•2 years ago
|
||
Updated•2 years ago
|
Assignee | ||
Updated•2 years ago
|
Updated•2 years ago
|
Comment 10•2 years ago
|
||
Backed out for causing xpcshell failures on test_ext_downloads_misc.js.
[task 2023-02-22T18:23:22.880Z] 18:23:22 INFO - TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js
[task 2023-02-22T18:23:24.883Z] 18:23:24 WARNING - TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | xpcshell return code: 0
[task 2023-02-22T18:23:24.883Z] 18:23:24 INFO - TEST-INFO took 1997ms
[task 2023-02-22T18:23:24.884Z] 18:23:24 INFO - >>>>>>>
[task 2023-02-22T18:23:24.884Z] 18:23:24 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-02-22T18:23:24.885Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-02-22T18:23:24.885Z] 18:23:24 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-02-22T18:23:24.886Z] 18:23:24 INFO - running event loop
[task 2023-02-22T18:23:24.886Z] 18:23:24 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | Starting setup check_remote
[task 2023-02-22T18:23:24.888Z] 18:23:24 INFO - (xpcshell/head.js) | test check_remote pending (2)
[task 2023-02-22T18:23:24.889Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true
[task 2023-02-22T18:23:24.890Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | check_remote - [check_remote : 1] testing from extension process - false == false
[task 2023-02-22T18:23:24.890Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2023-02-22T18:23:24.892Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2023-02-22T18:23:24.893Z] 18:23:24 INFO - (xpcshell/head.js) | test check_remote finished (2)
[task 2023-02-22T18:23:24.893Z] 18:23:24 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | Starting setup
[task 2023-02-22T18:23:24.894Z] 18:23:24 INFO - (xpcshell/head.js) | test pending (2)
[task 2023-02-22T18:23:24.894Z] 18:23:24 INFO - "downloadDir /tmp/xpc-profile-sdnqr1sz/temp/downloads"
[task 2023-02-22T18:23:24.899Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2023-02-22T18:23:24.900Z] 18:23:24 INFO - "removed 0 pre-existing downloads from history"
[task 2023-02-22T18:23:24.901Z] 18:23:24 INFO - "Extension attached"
[task 2023-02-22T18:23:24.901Z] 18:23:24 INFO - PID 20856 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T18:23:24.902Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2023-02-22T18:23:24.902Z] 18:23:24 INFO - (xpcshell/head.js) | test finished (2)
[task 2023-02-22T18:23:24.903Z] 18:23:24 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | Starting test_events
[task 2023-02-22T18:23:24.904Z] 18:23:24 INFO - (xpcshell/head.js) | test test_events pending (2)
[task 2023-02-22T18:23:24.904Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2023-02-22T18:23:24.905Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_events - [test_events : 333] download() succeeded - "success" == "success"
[task 2023-02-22T18:23:24.906Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_events - [test_events : 349] got onCreated and onChanged events - "success" == "success"
[task 2023-02-22T18:23:24.907Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2023-02-22T18:23:24.907Z] 18:23:24 INFO - (xpcshell/head.js) | test test_events finished (2)
[task 2023-02-22T18:23:24.908Z] 18:23:24 INFO - xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | Starting test_cancel
[task 2023-02-22T18:23:24.909Z] 18:23:24 INFO - (xpcshell/head.js) | test test_cancel pending (2)
[task 2023-02-22T18:23:24.909Z] 18:23:24 INFO - "http://localhost:38333/interruptible/interruptible.html?count=0"
[task 2023-02-22T18:23:24.910Z] 18:23:24 INFO - (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2023-02-22T18:23:24.911Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_cancel - [test_cancel : 356] download() succeeded - "success" == "success"
[task 2023-02-22T18:23:24.911Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_cancel - [test_cancel : 364] got created and changed events - "success" == "success"
[task 2023-02-22T18:23:24.912Z] 18:23:24 INFO - "download reached 15 bytes"
[task 2023-02-22T18:23:24.912Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_cancel - [test_cancel : 370] cancel() succeeded - "success" == "success"
<...>
[task 2023-02-22T18:23:24.978Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_file_removal - [test_file_removal : 761] removeFile() succeeded - "success" == "success"
[task 2023-02-22T18:23:24.978Z] 18:23:24 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Unix error 2 during operation remove on file /tmp/xpc-profile-sdnqr1sz/temp/downloads/file_download(1).txt (No such file or directory)" {file: "resource://gre/modules/ExtensionCommon.jsm" line: 818}]
[task 2023-02-22T18:23:24.978Z] 18:23:24 INFO - normalizeError@resource://gre/modules/ExtensionCommon.jsm:818:10
[task 2023-02-22T18:23:24.979Z] 18:23:24 INFO - recvAPICall/<@resource://gre/modules/ExtensionParent.jsm:1180:29
[task 2023-02-22T18:23:24.979Z] 18:23:24 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:238:6
[task 2023-02-22T18:23:24.979Z] 18:23:24 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:585:5
[task 2023-02-22T18:23:24.980Z] 18:23:24 INFO - @-e:1:1
[task 2023-02-22T18:23:24.980Z] 18:23:24 INFO - "
[task 2023-02-22T18:23:24.981Z] 18:23:24 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_file_removal - [test_file_removal : 764] removeFile() fails since the file was already removed. - "error" == "error"
[task 2023-02-22T18:23:24.981Z] 18:23:24 WARNING - TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_file_removal - [test_file_removal : 769] removeFile() failed on removed file. - "An unexpected error occurred" == "Could not remove download id 5 because the file doesn't exist"
[task 2023-02-22T18:23:24.981Z] 18:23:24 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js:test_file_removal:769
[task 2023-02-22T18:23:24.982Z] 18:23:24 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:238
[task 2023-02-22T18:23:24.982Z] 18:23:24 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:585
[task 2023-02-22T18:23:24.982Z] 18:23:24 INFO - -e:null:1
[task 2023-02-22T18:23:24.983Z] 18:23:24 INFO - exiting test
[task 2023-02-22T18:23:24.983Z] 18:23:24 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2023-02-22T18:23:24.983Z] 18:23:24 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:863:20
[task 2023-02-22T18:23:24.984Z] 18:23:24 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:964:5
[task 2023-02-22T18:23:24.984Z] 18:23:24 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:71:21
[task 2023-02-22T18:23:24.984Z] 18:23:24 INFO - Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2023-02-22T18:23:24.985Z] 18:23:24 INFO - equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2023-02-22T18:23:24.985Z] 18:23:24 INFO - test_file_removal@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js:769:8
[task 2023-02-22T18:23:24.986Z] 18:23:24 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:238:6
[task 2023-02-22T18:23:24.986Z] 18:23:24 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:585:5
[task 2023-02-22T18:23:24.986Z] 18:23:24 INFO - @-e:1:1
[task 2023-02-22T18:23:24.987Z] 18:23:24 INFO - exiting test
[task 2023-02-22T18:23:24.987Z] 18:23:24 INFO - "Force a GC"
[task 2023-02-22T18:23:24.987Z] 18:23:24 INFO - <<<<<<<
[task 2023-02-22T18:23:24.988Z] 18:23:24 INFO - INFO | Result summary:
[task 2023-02-22T18:23:24.988Z] 18:23:24 INFO - INFO | Passed: 238
[task 2023-02-22T18:23:24.988Z] 18:23:24 WARNING - INFO | Failed: 1
[task 2023-02-22T18:23:24.988Z] 18:23:24 WARNING - One or more unittests failed.
[task 2023-02-22T18:23:24.989Z] 18:23:24 INFO - INFO | Todo: 0
[task 2023-02-22T18:23:24.989Z] 18:23:24 INFO - INFO | Retried: 1
[task 2023-02-22T18:23:24.989Z] 18:23:24 INFO - SUITE-END | took 740s
[task 2023-02-22T18:23:24.990Z] 18:23:24 INFO - Node moz-http2 server shutting down ...
Assignee | ||
Updated•2 years ago
|
Comment 11•2 years ago
|
||
Comment 12•2 years ago
|
||
Backed out for causing failures on test_ext_downloads_misc.js
- backout: https://hg.mozilla.org/integration/autoland/rev/36a08c1e880b01705adbe65b53ab36b97a8a90d4
- push: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&selectedTaskRun=TtGqCrYbQGSzIi0rzRrlLw.0&revision=164869614132b094109b54e30bb15c1003b1db37
- push where failure was seen: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&selectedTaskRun=TtGqCrYbQGSzIi0rzRrlLw.0&revision=de7f205b0aed7ce85493ee0da780ddaa247b3c57&searchStr=xpcshell
- failure log: https://treeherder.mozilla.org/logviewer?job_id=406613548&repo=autoland&lineNumber=1989
TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | test_file_removeFile_permission_failure - [test_file_removeFile_permission_failure : 829] removeFile() fails due to missing dir perms - "success" == "error"
Assignee | ||
Updated•2 years ago
|
Comment 13•2 years ago
|
||
Comment 14•2 years ago
|
||
bugherder |
Comment 15•2 years ago
|
||
Since nightly and release are affected, beta will likely be affected too.
For more information, please visit auto_nag documentation.
Comment 16•2 years ago
|
||
Hello,
I attempted to verify the fix on the latest Nightly (112.0a1/20230226214053) under Windows 10 x64, Ubuntu 16.04 LTS and macOS 11.3.1.
Out of the three OSes I verified the fix on, only on Windows do I get some sort of error once I open the add-on debug console (see attached screenshot). On Linux and macOS, the extension will continuously perform its designated loop for thousands of iterations and no errors are logged.
On Windows the following are logged to console and I’m not sure these errors are the intended ones as per Comment 7. Will wait for confirmation before changing the bug status.
Error: An unexpected error occurred background.js:31:17
Uncaught (in promise) Error: Failed to download "test-downloads-removefile/mypath(7)": An unexpected error occurred background.js:33:16
Checking the default download folder reveals that the file mentioned in the second error is not deleted.
For more details, see the attached screenshot.
Comment 17•2 years ago
|
||
Assignee | ||
Comment 18•2 years ago
|
||
That looks as expected. The global browser console should have a more specific error.
Danny - I "resolved" the bug by correcting the unexpected error message. If you believe that the presence of the error is a bug in Firefox, please feel free to open a new bug report.
Comment 19•2 years ago
|
||
Confirmed the more specific error mentioned in Comment 18. See attached screenshot.
Marking Nightly 112 as Verified Fixed.
Comment 20•2 years ago
|
||
Comment 21•2 years ago
|
||
The patch landed in nightly and beta is affected.
:robwu, is this bug important enough to require an uplift?
- If yes, please nominate the patch for beta approval.
- If no, please set
status-firefox111
towontfix
.
For more information, please visit auto_nag documentation.
Assignee | ||
Updated•2 years ago
|
Description
•