Thanks, that is a really useful log...
Here is what I think happened
The file was written and queued for upload
2020/10/24 19:16:25 INFO : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: queuing for upload in 5s
The upload then started 5 seconds later
2020/10/24 19:16:30 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: starting upload
However something then opens the file for write
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: Open: flags=O_RDWR
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: newRWFileHandle:
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: >newRWFileHandle: err=<nil>
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: >Open: fd=sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3 (rw), err=<nil>
2020/10/24 19:16:38 DEBUG : /sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: >OpenFile: fd=sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3 (rw), err=<nil>
2020/10/24 19:16:38 DEBUG : /sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: >OpenEx: errc=0, fh=0x1
And writes some data at the start of the file
2020/10/24 19:16:38 DEBUG : /sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: Write: ofst=0, fh=0x1
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3(0xc001451140): _writeAt: size=4096, off=0
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3(0xc001451140): openPending:
Meanwhile the upload is still running writing data to the actual file.
Now rclone checks the fingerprint of the remote file. This causes the server to run the md5sum
command on the file. The remote file is in the process of uploading so the md5sum of the remote file has changed even though the upload isn't complete (this is unlike any other backend except local)
2020/10/24 19:16:38 DEBUG : sftp cmd = /something/sounds_zero/taylor\ deupree\ -\ northern/01-02-taylor\ deupree-northern.mp3
2020/10/24 19:16:38 DEBUG : sftp output = "b4febee818cadf8311e3e99bbcee7d7b /something/sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3\n"
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: checking remote fingerprint "23165404,2018-01-27 22:24:35 +0000 UTC,b4febee818cadf8311e3e99bbcee7d7b" against cached fingerprint "23165404,2018-01-27 22:24:35 +0000 UTC,4224518601e549258e053e6f180bae1e"
Now rclone sees that the remote has changed so the local data is out of date so deletes it. This is questionable - what rclone has detected here is a conflict - the local data got changed and (it thinks) the remote data got changed too.
I think this is the fundamental cause of the problem.
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: removing cached entry as stale (remote fingerprint "23165404,2018-01-27 22:24:35 +0000 UTC,b4febee818cadf8311e3e99bbcee7d7b" != cached fingerprint "23165404,2018-01-27 22:24:35 +0000 UTC,4224518601e549258e053e6f180bae1e")
Meanwhile we cancel the in-progress upload since the file has been written to locally.
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: cancelling writeback (uploading true) 0xc0004f4a10 item 2
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: cancelling upload
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: Removed after failed upload: context canceled
2020/10/24 19:16:38 ERROR : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: Failed to copy: Update ReadFrom failed: context canceled
2020/10/24 19:16:38 INFO : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: upload canceled
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: cancelled upload
And remove the cache file since rclone now is convinced the one on the sftp server is newer.
2020/10/24 19:16:38 INFO : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: removed cache file as stale (remote is different)
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: removed metadata from cache as stale (remote is different)
2020/10/24 19:16:38 DEBUG : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: truncate to size=23165404
However something got out of sync and we never created the file... What we should be doing is downloading the one from the server if there was a real conflict (not the one rclone just made up!)
2020/10/24 19:16:39 INFO : sounds_zero/taylor deupree - northern/01-02-taylor deupree-northern.mp3: vfs cache: downloader: error count now 1: vfs reader: failed to write to cache file: Open failed: file does not exist
Further analysis
- This could only happen on the SFTP or local backends. Fixing these to upload to a temporary name then rename it into place would fix this problem
- Deleting the dirty data seems incorrect to me
- You can probably work around this by increasing
--vfs-write-back
from its default of 5 seconds.
@leoluan since you are up to speed with VFS internals - what do you think - is that analysis correct?