1652296 - Links that use download attribute occasionally failing on save to Dropbox sync folder

Status: RESOLVED FIXED

(Firefox :: Downloads Panel, defect, P3)

Description

[voracity]

Attachment: savetest2.html

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

Steps to reproduce:

I created a HTML file with <a href="data:..." download="filename.txt"> link. I then open it in Firefox, and click the link to save the file to a Dropbox synced folder. I then choose to overwrite an existing file.

Actual results:

If I save it to a Dropbox sync folder over an existing file, it often (but not always) fails --- that is, it shows "Failed" in the Downloads dropdown. If I then click Retry, it (so far) always works.

I think it fails when I try to overwrite an existing file only. (I can't recall it failing when saving to a fresh file.)

By contrast:

1. If I save it to a normal folder, it works fine all the time
2. It saves fine to a Google Drive sync folder
3. Chrome always saves the file fine
4. If I load a plain text file in Firefox, and choose Menu -> Save Page As..., it always works. So it seems to be limited to page-generated saving, possibly just a[download] links.

Expected results:

It should, of course, always work.

I've attached the absolute minimal test case which shows the problem for me. Obviously, to replicate it, you'll need to save it to a Dropbox sync folder (on Win 10, presumably).

This took a really long time to narrow down. I appreciate it's very specific, but it's cost me some small lost work on a few occasions.

Comment 1

[voracity]

Just a note that I've been able to (again, intermittently) replicate it on a Windows 7 machine (with Dropbox, of course) and which was running Firefox 74.

This time I counted it: It failed on 2 out of 7 attempts to save the file to a Dropbox folder. It never failed out of 12 attempts to save the file to a normal folder.

(Can also provide video if it helps.)

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Comment 3

[voracity]

This obviously doesn't belong in Firefox Sync. I'm not sure where it does belong (maybe Core or maybe UI), but for now I've put it under Downloads Panel.

Comment 4

[Mike Kaply [:mkaply]]

Are there any errors in the console when this happens? I think this is probably the right component.

Comment 5

[voracity]

Nothing shows up in the web console (which is one of the things that made it a puzzle to narrow down). I've just remembered about the browser console, but nothing shows up there either. Not sure if there's anything else I can check?

Comment 6

[Mike Kaply [:mkaply]]

Confirming as I can easily recreate with your instructions by saving to my Dropbox folder.

Looking in DownloadsViewUI.jsm, this is the error/stack:

innerException: {…}
​fileName: "(unknown module)"
​lineNumber: undefined
​operation: "move"
​path: "C:\Users\mkaply\AppData\Local\Temp\dSvj2dKf.txt.part"
​stack: ""
​winLastError: 5
​<prototype>: {…}
message: "[Exception... "Failure" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://gre/modules/DownloadCore.jsm :: DownloadError :: line 1635" data: no]"
name: "DownloadError"
result: 2147500037
stack: "DownloadError@resource://gre/modules/DownloadCore.jsm:1670:16\nD_start/<@resource://gre/modules/DownloadCore.jsm:557:20\n"

Comment 7

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

That sounds like OS.File failing to move the file to the final destination... the unfortunately usual problem with long living Windows file locks? :(

Comment 8

[:Gijs (he/him)]

Mike, a bit of a shot in the dark - but we have a new framework for moving files to replace OS.File, called IOUtils. It uses our nsIFile backend but wraps it so it's easier to use from JS and does the IO off-main-thread, and in theory it might work better for cases like this. I don't have a Windows machine with Dropbox installed - is it easy for you to do an artifact build and swap out the 2 calls to OS.File.move in toolkit/components/downloads/DownloadCore.jsm with IOUtils.move (will need an await just like OS.File) and see if that fixes the issue?

Comment 9

[Mike Kaply [:mkaply]]

Still fails the same way with IOUtils.move

Comment 10

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:mak, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 11

[:Gijs (he/him)]

(In reply to Mike Kaply [:mkaply] from comment #6)

​winLastError: 5

Apparently this is an "access denied" error, and the internet (stackoverflow)'s suggestion for coping with it is... just trying again after a few ms? :-\

Feels pretty dumb. But perhaps that's our best option in the circumstances? Don't know if anyone has ideas on how to establish why we're not allowed to overwrite the file the first time 'round. :toshi, don't suppose you have ideas?

Comment 12

[Toshihito Kikuchi [:toshi]]

(In reply to voracity from comment #0)

I created a HTML file with <a href="data:..." download="filename.txt"> link. I then open it in Firefox, and click the link to save the file to a Dropbox synced folder. I then choose to overwrite an existing file.

I tried this steps on Win10 2004 several times, but no failure. Capturing file I/O with Process Monitor might be helpful..?

Comment 13

[:Gijs (he/him)]

(In reply to Toshihito Kikuchi [:toshi] from comment #12)

(In reply to voracity from comment #0)

I created a HTML file with <a href="data:..." download="filename.txt"> link. I then open it in Firefox, and click the link to save the file to a Dropbox synced folder. I then choose to overwrite an existing file.

I tried this steps on Win10 2004 several times, but no failure. Capturing file I/O with Process Monitor might be helpful..?

Mike, as you mentioned you could repro, can you try recording this failure to see what's what?

Comment 14

[Mike Kaply [:mkaply]]

Attachment: savefail.pml

It failed the first time for me (which is odd). I got a 0 bytes file.

I created a folder called test_folder in dropbox so I could filter on process monitor.

This PML shows all entries where path included test_folder when I saved from Firefox. ]

In the download manager it says "failed"

Comment 15

[Mike Kaply [:mkaply]]

Attachment: saveoverwritefail.PML

Here's the overwrite failing as well.

Comment 16

[Toshihito Kikuchi [:toshi]]

Sorry for the late response. Thank you for sharing the procmon dumps, Mike.

When Firefox saves a downloaded file over an existing file, it downloads a file in the %temp% folder first, then moves it to the destination via MoveFileEx called from here.

saveoverwritefail.PML successfully captured that call to MoveFileEx, that is appeared at 8/5/2020 10:39:34.2671475 PM, CreateFile to C:\Users\mkaply\Dropbox\test_folder. When I did a normal scenario without any downloading error, on the other hand, MoveFileEx was shown as CreateFile to the containing folder, and CloseFile to the destination file, but the latter one was not shown in saveoverwritefail.PML.

I found the pattern of saveoverwritefail.PML, only CreateFile to a folder, happened when the destination file was locked by another process. In that case, MoveFileExW fails with the error code 5, so that explains the situation well.

I believe the file was locked by dropbox.exe. I don't know why I cannot reproduce the issue on my end, but this can happen if dropbox.exe or any other application opens a destination file exclusively. Marco and Gijs, I don't think this is a bug on Firefox side. What we can do is to lock a file earlier, or display a more friendly message if we hit this situation?

Comment 17

[:Gijs (he/him)]

(In reply to Toshihito Kikuchi [:toshi] from comment #16)

I don't know why I cannot reproduce the issue on my end, but this can happen if dropbox.exe or any other application opens a destination file exclusively. Marco and Gijs, I don't think this is a bug on Firefox side.

comment #0 suggests that Chrome doesn't have the same problem. What are they doing differently? Reporter: is the flow you use to save with Chrome different, perhaps?

Mike/reporter, any ideas why the locking behaviour you and the reporter are seeing is different from what :toshi is seeing? Is it maybe correlated with whether the file being overwritten was recently written to (ie do you save the same file multiple times in succession or something) so dropbox is trying to sync it ?

What we can do is to lock a file earlier, or display a more friendly message if we hit this situation?

We won't know what the file being overwritten is until the user makes a choice in the "save as" dialog. At that point, given this is a tiny example file, the file will have already been saved to the temp dir and so the move should be pretty much instantaneous, so I don't see why locking it first would help? Is there evidence in the dump of why/when dropbox locks the file?

It looks like MoveFileEx has an optional flag, MOVEFILE_COPY_ALLOWED, which at least some parts of Chrome use. Would using that here be likely to help?

(Marco's out, and I think we still don't fully understand the issue, so clearing his needinfo for now.)

Comment 18

[Mike Kaply [:mkaply]]

I wonder if it has to do with the Dropbox version or type? I have the enterprise version of Dropbox.

I think there is definitely something stranger going on because even if I wait 30+ seconds, it still fails on the same Firefox instance. Dropbox would have long since synced it. And Chrome is not having the same issue.

Comment 19

[voracity]

I don't have the enterprise version of Dropbox, so I don't believe the issue's there. All that's required for me to replicate is that the file already be there. Any amount of time can pass between saves, and the problem still occurs. For instance, I just tested again, and it failed the first time --- and the last sync of any file in my Dropbox would have been a few hours ago. (That particular file would have been weeks ago now.)

AFAICT, the flow I used with Chrome is as identical as it can be to Firefox. I (long ago) setup both Firefox and Chrome to popup a "Save As..." dialog by default. In both Firefox and Chrome, I click the "Save" link in my minimal test case, then click "Save" in the Windows file dialog to save/overwrite the file into the Dropbox folder.

As I mentioned, I can replicate it on Windows 10 (~2 yrs old with SSD) and Windows 7 (~10 yrs old, also with SSD) --- two entirely different systems, but they are on the same network. (NB: I tried toggling Dropbox's "Enable LAN Sync" option off, and it made no difference.)

Note also that I can't ever recall having similar issues in any other software application when saving to Dropbox (e.g. I use Notepad++ extensively on my Dropbox files, as well as a variety of other editors, IDEs, office apps, etc...)

The final thing to note (in case it wasn't clear) is that the existing file is being overwritten with a 0 byte file. So, it's not just failing to save --- it's deleting the existing file and creating a new one, but is unable to put anything in it. That seems unusual --- I would have thought something like MoveFile would be atomic with respect to file locking.

Also, MOVEFILE_COPY_ALLOWED seems to be for moving things to other drives, but all my folders (temp, Dropbox, etc.) are on the same drive.

Comment 20

[Toshihito Kikuchi [:toshi]]

When I analyzed the procmon dump more closely and compared it to what happened on my local environment, the following File I/O events happened:

1. Firefox deleted filename.txt at HelperAppDlg.jsm#377
2. Firefox created an empty file of filename.txt at HelperAppDlg.jsm#447
3. Dropbox.exe started to sync filename.txt with the server
4. Move the downloaded file from %temp% to filename.txt at osfile_win_front.jsm#679

If 4) is triggered while 3) is still in progress, 4) fails with access denied, and an empty file created at 2) is left. I think that's what happened.

Comment 21

[:Gijs (he/him)]

(In reply to Toshihito Kikuchi [:toshi] from comment #20)

When I analyzed the procmon dump more closely and compared it to what happened on my local environment, the following File I/O events happened:

1. Firefox deleted filename.txt at HelperAppDlg.jsm#377
2. Firefox created an empty file of filename.txt at HelperAppDlg.jsm#447
3. Dropbox.exe started to sync filename.txt with the server
4. Move the downloaded file from %temp% to filename.txt at osfile_win_front.jsm#679

If 4) is triggered while 3) is still in progress, 4) fails with access denied, and an empty file created at 2) is left. I think that's what happened.

Gah. This makes sense out of everything that was here. Thanks for investigating. I think I can come up with a fix...

Comment 22

[:Gijs (he/him)]

This logic was originally introduced in bug 341771 after changes in bug 236514. It seems as a result of previous refactors, it should be reasonably straightforward to avoid the separate delete and instead just ignore the "oh no we need a suffix" code that tries to create a unique file if one exists. Because we always download to a .part file and then move into place, this should Just Work, in theory.

Trying to see if I can come up with a way to test this scenario in automated fashion...

Comment 23

[:Gijs (he/him)]

Attachment: Bug 1652296 - do not delete overwritten downloaded files separately, r?mkaply

Comment 24

[:Gijs (he/him)]

Attachment: Bug 1652296 - test that we do not delete files immediately when the user chooses to overwrite for a download, r?mkaply

Depends on D86985

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c0110f0d90bf
do not delete overwritten downloaded files separately, r=mkaply
https://hg.mozilla.org/integration/autoland/rev/e6f95be871b0
test that we do not delete files immediately when the user chooses to overwrite for a download, r=mkaply

Comment 26

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/c0110f0d90bf
https://hg.mozilla.org/mozilla-central/rev/e6f95be871b0