Closed Bug 1807815 Opened 2 years ago Closed 2 years ago

downloads.removeFile fails with "file doesn't exist" occasionally

Categories

(WebExtensions :: General, defect, P3)

Firefox 108
defect

Tracking

(firefox108 wontfix, firefox109 wontfix, firefox110 wontfix, firefox111 wontfix, firefox112 verified)

VERIFIED FIXED
112 Branch
Tracking Status
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)

Attached file test-bug - downloads.removeFile.7z (obsolete) —

User Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0

Steps to reproduce:

  1. Download the test extension and install it.
  2. The extension will automatically perform tests for a path under the default download directory.
  3. 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.

Attachment #9309995 - Attachment is obsolete: true
Summary: downloads.removeFile fails unexpectedly → downloads.removeFile fails with "file doesn't exist" occasionally

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.

Component: Untriaged → Downloads Panel

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.

Component: Downloads Panel → General
Product: Firefox → WebExtensions

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.

Status: UNCONFIRMED → NEW
Ever confirmed: true
Attached image 2023-01-06_09h25_19.png

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.

Flags: needinfo?(rob)
Severity: -- → S3
Priority: -- → P3

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.

Flags: needinfo?(rob)
Assignee: nobody → rob
Status: NEW → ASSIGNED
Whiteboard: [addons-jira]
Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/ac90f791ff82 Throw accurate errors from downloads.removeFile r=zombie

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 ...
Flags: needinfo?(rob)
Flags: needinfo?(rob)
See Also: → 1772932
Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/164869614132 Throw accurate errors from downloads.removeFile r=zombie

Backed out for causing failures on test_ext_downloads_misc.js

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"
Flags: needinfo?(rob)
Flags: needinfo?(rob)
Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/1e3090252ef9 Throw accurate errors from downloads.removeFile r=zombie
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 112 Branch

Since nightly and release are affected, beta will likely be affected too.
For more information, please visit auto_nag documentation.

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.

Attached image 2023-02-27_10h39_53.png

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.

Status: RESOLVED → VERIFIED

Confirmed the more specific error mentioned in Comment 18. See attached screenshot.

Marking Nightly 112 as Verified Fixed.

Attached image 2023-02-27_13h45_51.png

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 to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(rob)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: