Consistently getting "corrupted on transfer: sizes differ" syncing to an SMB share

yichi_yang · October 7, 2023, 7:13pm

What is the problem you are having with rclone?

My use case is to backup the entire user folder on a Windows 11 box to an SMB share. I follow How to enable VSS for rclone and rclone sync from a VSS snapshot to ensure files don't change in the process (exactly the same setup as in the guide but with different rclone sync arguments, see below). However, I'm consistently getting corrupted on transfer: sizes differ errors for a small fixed set of files (see below).

Run the command 'rclone version' and share the full output of the command.

rclone v1.64.0
- os/version: Microsoft Windows 11 Education 22H2 (64 bit)
- os/kernel: 10.0.22621.2283 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.21.1
- go/linking: static
- go/tags: cmount

Which cloud storage system are you using? (eg Google Drive)

SMB share on a TrueNAS box.

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

rclone sync C:\snapshot\Users\Yichi truenas:/pc-backup --filter-from pc-backup-filter.txt --transfers=8 --ignore-existing --retries 1

Please run 'rclone config redacted' and share the full output. If you get command not found, please make sure to update rclone.

[truenas]
type = smb
host = XXX
user = XXX
pass = XXX

A log from the command that you were trying to run with the `-vv` flag

As there are too many files in the user folder, I pasted below the logs without the -vv flag. Note these files cause corrupted on transfer: sizes differ every time.

>rclone sync C:\snapshot\Users\Yichi truenas:/pc-backup --filter-from pc-backup-filter.txt --transfers=8 --ignore-existing --retries 1
2023/10/07 11:44:38 NOTICE: Application Data: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: Cookies: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: Local Settings: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: My Documents: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: NetHood: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: PrintHood: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: Recent: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: SendTo: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: Start Menu: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:38 NOTICE: Templates: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:39 NOTICE: Documents/My Music: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:39 NOTICE: Documents/My Pictures: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:39 NOTICE: Documents/My Videos: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:40 NOTICE: AppData/Local/Application Data: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:40 NOTICE: AppData/Local/History: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:40 NOTICE: AppData/Local/Temporary Internet Files: Can't follow symlink without -L/--copy-links
2023/10/07 11:44:52 ERROR : AppData/Local/Intel/SUR/QUEENCREEK/intermediate_data/u-000030.db: Failed to copy: failed to open source object: Access is denied.
2023/10/07 11:44:56 ERROR : AppData/Local/NVIDIA/NvBackend/journalBS.jour.dat: corrupted on transfer: sizes differ 28392 vs 28580
2023/10/07 11:44:56 ERROR : AppData/Local/NVIDIA/NvBackend/backend.log: corrupted on transfer: sizes differ 8521778 vs 13094968
2023/10/07 11:44:59 ERROR : AppData/Local/NVIDIA Corporation/NVIDIA Share/CxNative_NVIDIA Share.log: corrupted on transfer: sizes differ 40445 vs 41639
2023/10/07 11:44:59 ERROR : AppData/Local/NVIDIA Corporation/NVIDIA Share/debug.log: corrupted on transfer: sizes differ 33264 vs 47584
2023/10/07 11:44:59 ERROR : AppData/Local/NVIDIA Corporation/NvNode/nvnode.log: corrupted on transfer: sizes differ 583816 vs 609564
2023/10/07 11:45:00 ERROR : AppData/Local/NVIDIA Corporation/NVIDIA Share/console.log: corrupted on transfer: sizes differ 838849 vs 1017563
2023/10/07 11:45:07 ERROR : AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/Mail/smart mailboxes/Inbox.msf: corrupted on transfer: sizes differ 0 vs 3015
2023/10/07 11:45:07 ERROR : AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/ImapMail/imap.gmail.com/INBOX.msf: corrupted on transfer: sizes differ 5462344 vs 5470491
2023/10/07 11:45:15 ERROR : AppData/Local/Steam/htmlcache/Local Storage/leveldb/000016.log: corrupted on transfer: sizes differ 19710 vs 20952
2023/10/07 11:45:25 ERROR : AppData/Local/Microsoft/OneDrive/logs/ListSync/Business1/Nucleus-2023-10-06.2030.5232.2.aodl: corrupted on transfer: sizes differ 105729 vs 135864
2023/10/07 11:45:31 NOTICE: AppData/Local/Microsoft/Windows/Temporary Internet Files: Can't follow symlink without -L/--copy-links
2023/10/07 11:45:36 ERROR : AppData/Local/Microsoft/Edge/User Data/Default/EdgeCoupons/coupons_data.db/000062.log: corrupted on transfer: sizes differ 411076 vs 411646
2023/10/07 11:45:47 NOTICE: AppData/Local/Microsoft/Windows/INetCache/Content.IE5: Can't follow symlink without -L/--copy-links
2023/10/07 11:45:48 ERROR : AppData/Local/Microsoft/Windows/Notifications/wpndatabase.db-wal: corrupted on transfer: sizes differ 494432 vs 2183632
2023/10/07 11:45:54 ERROR : AppData/Local/Microsoft/Edge/User Data/Default/Sync Data/LevelDB/000003.log: corrupted on transfer: sizes differ 78726 vs 79269
2023/10/07 11:46:04 ERROR : AppData/Local/Packages/Microsoft.WindowsNotepad_8wekyb3d8bbwe/LocalState/WindowState/85499f82-33be-48ce-842e-b0e6f7d28f12.0.bin: corrupted on transfer: sizes differ 0 vs 84
2023/10/07 11:46:04 ERROR : AppData/Local/Packages/Microsoft.WindowsNotepad_8wekyb3d8bbwe/LocalState/WindowState/85499f82-33be-48ce-842e-b0e6f7d28f12.1.bin: corrupted on transfer: sizes differ 0 vs 84
2023/10/07 11:46:50 ERROR : smb://yichi@truenas.local:445/pc-backup/: not deleting files as there were IO errors
2023/10/07 11:46:50 ERROR : smb://yichi@truenas.local:445/pc-backup/: not deleting directories as there were IO errors
2023/10/07 11:46:50 ERROR : Attempt 1/1 failed with 16 errors and: corrupted on transfer: sizes differ 0 vs 84
2023/10/07 11:46:50 Failed to sync with 16 errors: last error was: corrupted on transfer: sizes differ 0 vs 84

I tried to sync one of the offending files with -vv, but interestingly that works without issue.

>rclone sync C:\snapshot\Users\Yichi\AppData\Roaming\Thunderbird\Profiles\6gfcsr78.default-release\ImapMail\imap.gmail.com\INBOX.msf truenas:/pc-backup/test --filter-from pc-backup-filter.txt --transfers=8 --ignore-existing --retries 1 -vv
2023/10/07 11:48:42 DEBUG : rclone: Version "v1.64.0" starting with parameters ["rclone" "sync" "C:\\snapshot\\Users\\Yichi\\AppData\\Roaming\\Thunderbird\\Profiles\\6gfcsr78.default-release\\ImapMail\\imap.gmail.com\\INBOX.msf" "truenas:/pc-backup/test" "--filter-from" "pc-backup-filter.txt" "--transfers=8" "--ignore-existing" "--retries" "1" "-vv"]
2023/10/07 11:48:42 DEBUG : Creating backend with remote "C:\\snapshot\\Users\\Yichi\\AppData\\Roaming\\Thunderbird\\Profiles\\6gfcsr78.default-release\\ImapMail\\imap.gmail.com\\INBOX.msf"
2023/10/07 11:48:42 DEBUG : Using config file from "C:\\Users\\Yichi\\AppData\\Roaming\\rclone\\rclone.conf"
2023/10/07 11:48:42 DEBUG : fs cache: adding new entry for parent of "C:\\snapshot\\Users\\Yichi\\AppData\\Roaming\\Thunderbird\\Profiles\\6gfcsr78.default-release\\ImapMail\\imap.gmail.com\\INBOX.msf", "//?/C:/snapshot/Users/Yichi/AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/ImapMail/imap.gmail.com"
2023/10/07 11:48:42 DEBUG : Creating backend with remote "truenas:/pc-backup/test"
2023/10/07 11:48:42 DEBUG : fs cache: renaming cache item "truenas:/pc-backup/test" to be canonical "truenas:pc-backup/test"
2023/10/07 11:48:42 DEBUG : INBOX.msf: Need to transfer - File not found at Destination
2023/10/07 11:48:43 INFO  : INBOX.msf: Copied (new)
2023/10/07 11:48:43 INFO  :
Transferred:        5.217 MiB / 5.217 MiB, 100%, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         1.3s

2023/10/07 11:48:43 DEBUG : 7 go routines active
2023/10/07 11:48:43 DEBUG : smb://yichi@truenas.local:445/pc-backup/test: Closing 2 unused connections

I'm new to rclone so I'm a bit clueless. Please let me know what additional information might be helpful. Thanks!

asdffdsa · October 7, 2023, 7:44pm

welcome to the forum,

tl;dr: try --local-no-preallocate

hi, i wrote that wiki, glad that you using it.
i have been using that basic procedure, many, many thousands of times.
tho, long ago, i have converted it to a python script.

i run a bit different approach.

for local to local, local to smb, i do not use rclone at all.
if using rclone to access smb/samba, i do not use rclone smb remote.
as it lacking many basic features, such as hashes for file verification.
instead, i use net use to create the smb mountpoint and use that as the dest.
creating the vss snapshot on the same drive is not a good idea.
from my wiki, looks like you are not using any of the three variants i suggested.
i use variant #3
and on the truenas, what is the file system that samba uses?
i ran into an issue on WSL, and i wrote a detailed topic about it somewhere in the forum.

on all machines i manage, there is a b: drive, can be just 1GiB in size, and is uses for the snapshot creation.
so with rclone, 7zip, etc, the source is always starts b:\ and looks something like

DEBUG : rclone: Version "v1.63.0" starting with parameters ["rclone.exe" "sync" "b:\\falconer\\vss\\data_files_wasabi_en07-data-crypt_20230820.154816\\data" "wasabi_en07-data-crypt:en07data/rclone/backup" "--backup-dir=wasabi_en07-data-crypt:en07data/rclone/archive/20230820.154816" "--exclude-from=d:\\falconer\\rr\\data\\rclone.exclude.txt" "--stats=5h" "--log-level=DEBUG" "--log-file=d:\\falconer\\backups\\data_files_wasabi_en07-data-crypt\\logs\\20230820.154816\\rclone.log" "--config=rclone.conf"]

yichi_yang · October 7, 2023, 8:20pm

@asdffdsa thanks for the pointers!

I assume you mean mount the SMB share locally, use it as a local remote, and then use --local-no-preallocate to turn off preallocation?

I believe it's a customized version of OpenZFS.

Yes I did run into issues on the Windows side where rclone can't read symlinks created in WSL. I have those paths filtered out for now. Do you happen to have a link to the post you mentioned?

asdffdsa · October 7, 2023, 8:29pm

sure.

yes, to mount the samba share locally using native windows os.
no, as i do not use local remote. i copy direct, like so
rclone copy c:\folder \\server\share

https://forum.rclone.org/t/rclone-copy-fails-to-wsl2-dos-copy-works/38351

yichi_yang · October 7, 2023, 8:56pm

Got it, thanks. I gave that a try, but I'm getting similar errors:

>rclone sync C:\snapshot\Users\Yichi \\truenas.local\pc-backup --local-no-preallocate --filter-from pc-backup-filter.txt  --transfers=8 --ignore-existing --retries 1
2023-10-07 13:44:13 NOTICE: Application Data: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Cookies: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Local Settings: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: My Documents: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: NetHood: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: PrintHood: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Recent: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: SendTo: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Start Menu: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Templates: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Documents/My Music: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Documents/My Pictures: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: Documents/My Videos: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: AppData/Local/Application Data: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: AppData/Local/History: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:13 NOTICE: AppData/Local/Temporary Internet Files: Can't follow symlink without -L/--copy-links
2023-10-07 13:44:26 NOTICE: AppData/Local/NVIDIA/NvBackend/backend.log.cepajoc3.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 8521778 to 13575822)
2023-10-07 13:44:26 NOTICE: AppData/Local/NVIDIA/NvBackend/journalBS.jour.dat.hisunes5.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 28392 to 28580)
2023-10-07 13:44:26 ERROR : AppData/Local/NVIDIA/NvBackend/backend.log: Failed to copy: can't copy - source file is being updated (size changed from 8521778 to 13575822)
2023-10-07 13:44:26 ERROR : AppData/Local/NVIDIA/NvBackend/journalBS.jour.dat: Failed to copy: can't copy - source file is being updated (size changed from 28392 to 28580)
2023-10-07 13:44:29 NOTICE: AppData/Local/NVIDIA Corporation/NVIDIA Share/CxNative_NVIDIA Share.log.suruhuc2.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 40445 to 41639)
2023-10-07 13:44:29 NOTICE: AppData/Local/NVIDIA Corporation/NVIDIA Share/console.log.tenuhis3.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 838849 to 1023141)
2023-10-07 13:44:29 NOTICE: AppData/Local/NVIDIA Corporation/NVIDIA Share/debug.log.guhamum5.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 33264 to 47888)
2023-10-07 13:44:29 ERROR : AppData/Local/NVIDIA Corporation/NVIDIA Share/CxNative_NVIDIA Share.log: Failed to copy: can't copy - source file is being updated (size changed from 40445 to 41639)
2023-10-07 13:44:29 ERROR : AppData/Local/NVIDIA Corporation/NVIDIA Share/console.log: Failed to copy: can't copy - source file is being updated (size changed from 838849 to 1023141)
2023-10-07 13:44:29 ERROR : AppData/Local/NVIDIA Corporation/NVIDIA Share/debug.log: Failed to copy: can't copy - source file is being updated (size changed from 33264 to 47888)
2023-10-07 13:44:30 NOTICE: AppData/Local/NVIDIA Corporation/NvNode/nvnode.log.lepakod0.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 583816 to 624586)
2023-10-07 13:44:30 ERROR : AppData/Local/NVIDIA Corporation/NvNode/nvnode.log: Failed to copy: can't copy - source file is being updated (size changed from 583816 to 624586)
2023-10-07 13:44:36 NOTICE: AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/Mail/smart mailboxes/Inbox.msf.kecayeq0.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 0 to 2981)
2023-10-07 13:44:36 ERROR : AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/Mail/smart mailboxes/Inbox.msf: Failed to copy: can't copy - source file is being updated (size changed from 0 to 2981)
2023-10-07 13:44:37 NOTICE: AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/ImapMail/imap.gmail.com/INBOX.msf.kiqoveq6.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 0 to 5450499)
2023-10-07 13:44:37 ERROR : AppData/Roaming/Thunderbird/Profiles/6gfcsr78.default-release/ImapMail/imap.gmail.com/INBOX.msf: Failed to copy: can't copy - source file is being updated (size changed from 0 to 5450499)
2023-10-07 13:44:47 NOTICE: AppData/Local/Steam/htmlcache/Local Storage/leveldb/000016.log.tasuqer7.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 19710 to 20952)
2023-10-07 13:44:47 ERROR : AppData/Local/Steam/htmlcache/Local Storage/leveldb/000016.log: Failed to copy: can't copy - source file is being updated (size changed from 19710 to 20952)
2023-10-07 13:44:58 NOTICE: AppData/Local/Microsoft/OneDrive/logs/ListSync/Business1/Nucleus-2023-10-06.2030.5232.2.aodl.hotodov7.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 105729 to 135864)
2023-10-07 13:44:58 ERROR : AppData/Local/Microsoft/OneDrive/logs/ListSync/Business1/Nucleus-2023-10-06.2030.5232.2.aodl: Failed to copy: can't copy - source file is being updated (size changed from 105729 to 135864)
2023-10-07 13:45:04 NOTICE: AppData/Local/Microsoft/Windows/Temporary Internet Files: Can't follow symlink without -L/--copy-links
2023-10-07 13:45:10 NOTICE: AppData/Local/Microsoft/Edge/User Data/Default/EdgeCoupons/coupons_data.db/000062.log.mubekaf5.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 411076 to 411722)
2023-10-07 13:45:10 ERROR : AppData/Local/Microsoft/Edge/User Data/Default/EdgeCoupons/coupons_data.db/000062.log: Failed to copy: can't copy - source file is being updated (size changed from 411076 to 411722)
2023-10-07 13:45:22 NOTICE: AppData/Local/Microsoft/Windows/INetCache/Content.IE5: Can't follow symlink without -L/--copy-links
2023-10-07 13:45:23 NOTICE: AppData/Local/Microsoft/Windows/Notifications/wpndatabase.db-wal.duyijar2.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 494432 to 2476152)
2023-10-07 13:45:23 ERROR : AppData/Local/Microsoft/Windows/Notifications/wpndatabase.db-wal: Failed to copy: can't copy - source file is being updated (size changed from 494432 to 2476152)
2023-10-07 13:45:30 NOTICE: AppData/Local/Microsoft/Edge/User Data/Default/Sync Data/LevelDB/000003.log.jalukep8.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 78726 to 79269)
2023-10-07 13:45:30 ERROR : AppData/Local/Microsoft/Edge/User Data/Default/Sync Data/LevelDB/000003.log: Failed to copy: can't copy - source file is being updated (size changed from 78726 to 79269)
2023-10-07 13:45:40 NOTICE: AppData/Local/Packages/Microsoft.WindowsNotepad_8wekyb3d8bbwe/LocalState/WindowState/23a5f4fe-5096-4bdb-9552-48d4c2bfbfcc.0.bin.geweqev4.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 52 to 100)
2023-10-07 13:45:40 ERROR : AppData/Local/Packages/Microsoft.WindowsNotepad_8wekyb3d8bbwe/LocalState/WindowState/23a5f4fe-5096-4bdb-9552-48d4c2bfbfcc.0.bin: Failed to copy: can't copy - source file is being updated (size changed from 52 to 100)
2023-10-07 13:46:23 ERROR : Local file system at //?/UNC/truenas.local/pc-backup: not deleting files as there were IO errors
2023-10-07 13:46:23 ERROR : Local file system at //?/UNC/truenas.local/pc-backup: not deleting directories as there were IO errors

Since the source is a VSS, I think these files should be immutable? Not sure what's going on here.

I'm using the version outlined in the "how to" section in your guide and thus the path C:\snapshot (thanks for the guide BTW). I'll look into the variants. If I understand correctly, this (edit: I mean the variants) only makes it less confusing, but should not affect the results?

Edit: for reference, my VSS setup
below: vs.cmd

set PATH=%PATH%;C:\Program Files (x86)\Windows Kits\10\bin\10.0.22621.0\x64
vshadow.exe -nw -script=setvars.cmd -exec=exec.cmd c:

below: exec.cmd

rem Load the the variables created by vshadow.exe
call setvars.cmd

rem Create the symbolic link to the snapshot (the backslash after shadow_device_1 is important!)
mklink /d C:\snapshot\ %shadow_device_1%\

rem Execute rclone with the source as c:\snapshot\data\, not c:\data\
rclone sync C:\snapshot\Users\Yichi \\truenas.local\pc-backup^
    --local-no-preallocate^
    --filter-from pc-backup-filter.txt^
    --transfers=8^
    --ignore-existing^
    --retries 1^
    --progress

rem Delete the symbolic link
rmdir C:\snapshot\

asdffdsa · October 7, 2023, 9:07pm

tl;dr - maybe try --inplace

well, if that is correct, then must look elsewhere.
create a test, not using rclone, not using truenas, not using smb/samba

best to remove rclone from your testing, pick another copy tool.
or at least, create a batch script to run rclone and that copy tool against the same snapshot.
compare the results.

as i mentioned, i do not use rclone for local/smb/samba, might be some quirks i have not encountered.

yes, that should be correct.
tho, in the last fours years, i have used variant #3 only, on over a dozen desktop and servers.
so doing it your way, could have quirks i have not encountered.

tho, just now, as i re-read my wiki, i noticed that i wrote this about #3 and i do not remember my logic?
"This is what I do as this is the most reliable.

and hard to debug your situation, maybe a truenas issue, maybe a samba config, maybe using wrong version of vshadow.exe, windows config issue, maybe try running rclone as system user, could be anything.

yichi_yang · October 7, 2023, 10:14pm

@asdffdsa thanks for your help. I played with different configurations but unfortunately nothing works.

I did a bit of digging, it seems when rclone complains source file is being updated (size changed from x to y),

x is always the same as the "size" (right click > properties) of the file in the VSS snapshot.
y is the same as or close to "size on disk" (right click > properties) of the file in the VSS snapshot. The "size on disk" of the file in the VSS snapshot tends to be the same as the current "size on disk" of the file (i.e., not in the VSS snapshot).

Could this be related to how rclone gets the size of the file (i.e., os.Lstat and os.File.Stat) and the quirks of VSS? Might need some input from the maintainers of rclone to figure this out.

yichi_yang · October 7, 2023, 11:41pm

Seems to be a duplicate of this (unresolved) thread.

asdffdsa · October 8, 2023, 2:54am

tl;dr, did more testing, still not having issues with vss snapshots.

yes, i am aware of the link you posted.
the OP was using an very old version of rclone and and old version of windows.
in the end, the OP stopped posting so it never got solved, assuming it was a rclone issue at all.

in your case, running special education edition of windows. and there are real difference between versions.

the files in the your debug logs looks like some of the source files are open, in-use, locked by thunderbird and other apps.
as such, given that thunderbird does not implement a vss writer for its database files and logs, not possible to use vss to backup it up reliably.

anyhoo, it has been a while since i used rclone on local, so i did more testing with rclone.
again, i could not replicate your issue.

and i made sure that thunderbird was open and in-use.
let's use, cookies.sqlite-shm, which is open, in-use and locked by thunderbird.

and here are the debug logs

rclone.exe copy b:\rclone\vss\test\Users\user01\AppData\Roaming \\vserver03\test --checksum --local-no-check-updated -vv --retries=1 
DEBUG : rclone: Version "v1.64.0" starting with parameters ["c:\\data\\rclone\\rclone.exe" "copy" "b:\\rclone\\vss\\test\\Users\\user01\\AppData\\Roaming" "\\vserver03\test" "--checksum" "--local-no-check-updated" "-vv" "--retries=1"]
DEBUG : Creating backend with remote "b:\\rclone\\vss\\test\\Users\\user01\\AppData\\Roaming"
DEBUG : Using config file from "c:\\data\\rclone\\rclone.conf"
DEBUG : local: detected overridden config - adding "{yKcAd}" suffix to name
DEBUG : fs cache: renaming cache item "b:\\rclone\\vss\\test\\Users\\user01\\AppData\\Roaming" to be canonical "local{yKcAd}://?/b:/rclone/vss/test/Users/user01/AppData/Roaming"
DEBUG : Creating backend with remote "\\vserver03\test"
DEBUG : local: detected overridden config - adding "{yKcAd}" suffix to name
DEBUG : fs cache: renaming cache item "\\vserver03\test" to be canonical "local{yKcAd}://?/UNC/vserver03/v$/test"
...snip...
DEBUG : Thunderbird/Profiles/idsc7o79.default-release/cookies.sqlite-shm: Need to transfer - File not found at Destination
...snip...
DEBUG : Thunderbird/Profiles/idsc7o79.default-release/cookies.sqlite-shm: md5 = 3e2ea87f858de0f6712d18bda9d5aba1 OK
...snip...
Transferred:   	  852.936 MiB / 852.936 MiB, 100%, 5.622 MiB/s, ETA 0s
Transferred:         6815 / 6815, 100%

rclone.exe check  b:\rclone\vss\test\Users\user01\AppData\Roaming \\vserver03\test --local-no-check-updated  -vv --retries=1 
DEBUG : Thunderbird/Profiles/idsc7o79.default-release/cookies.sqlite-shm: md5 = 3e2ea87f858de0f6712d18bda9d5aba1 OK
DEBUG : Thunderbird/Profiles/idsc7o79.default-release/cookies.sqlite-shm: OK
...snip...
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:              6815 / 6815, 100%

yichi_yang · October 8, 2023, 2:58am

I think that's why (you explicitly disabled that check)?

Anyway, like you said in that other post, I plan to stick to filtering out AppData/Local and manually backing up things like Thunderbird profiles (for the same reason you mentioned).

asdffdsa · October 11, 2023, 3:26pm

most weclome, i am glad that you found my wiki about vss and was able to implement it.

well, rclone should complain. the file size does change during copy; from x to y

sorry, perhaps i am not still not fully understanding your specific issue with rclone?

yichi_yang · October 11, 2023, 4:54pm

I think it's essentially the same problem as

When I rclone sync from a local VSS snapshot (the destination doesn't matter, tried local and sftp, same behavior), rclone complains source file is being updated (although I verified manually at least the file size in the snapshot didn't change).

asdffdsa · October 11, 2023, 6:16pm

if the file size changes during copy operation, then rclone let's you know.
imho, that is the correct behavior.

what else would you expect rclone to do?

yichi_yang · October 11, 2023, 6:38pm

I think I'm experiencing the same issue as you did here:

Not sure if I've made my point clear, but my source is also write-protected (in a VSS snapshot) and I don't expect their size to change. I'm pretty confident it's the same issue you reported in the above post.

I agree with @ncw that it probably has something to do with VSS (rclone somehow fails to get the correct file size because of VSS related issues and incorrectly reports those files as changing in size).

I do see @ncw asking for a minimal reproduction example - I can take a stab at that over the weekend.

asdffdsa · October 11, 2023, 8:41pm

i believe i have found another legit issue with rclone+vss that needs to be fixed.
i would like to be able to switch to and focus that.

so, i hope we can agree, in your case.
corrupted on transfer: sizes differ is the correct, expected behavior.

your point is clear. the source is a vss snapshot that is write-protected.
you are using my wiki about vss and so am i.
the same technique i have used on a daily basis for all my backups for over the last four years, on over a dozen desktops, servers and vm.

this is the root of confusion.
believe me, for a write-protected, read-only vss snapshot, that is a more than a valid assumption.
in my humble opinion, not a tested conclusion.

this is not about the source file. i agree that the source file never changes.
in this specific case, not about rclone.

this is about the copy operation itself as performed by windows os.
that is where the change happens.
rclone copies the source file in the same way as every copy tool i have tested.

as i mentioned, i suggested testing on other copy tools.

all the copied files have the same file size.
all the copied files have the same md5 hash.

here are some sample commands

fastcopy.exe /cmd=sync /no_ui /filelog=.\fc.log "t:\places.sqlite-wal" /to="d:\test\copied.by.fastcopy"
copy t:\places.sqlite-wal d:\test\copied.by.dos
powershell /c copy t:\places.sqlite-wal d:\test\copied.by.powershell

note: t: is using variant #1 from my wiki, to make it easier to discuss and read debug logs.
since your logs had issues with thunderbird profile files, i have chosen to focus on that.
if you could do that same in your testing, that would be great

subst
T:\: => b:\rclone\vss\system\Users\user01\AppData\Roaming\Thunderbird\Profiles\idsc7o79.default-release

and here is some output from my testing,
rclone produces the same file size and the same hash as other copy tools.

from my log, source file is being updated (size changed from 1278920 to 1934760)
the source file size is 1278920, which is correct
the dest file size is 1934760, which is correct

the size and hash of the source file

dir t:\places.sqlite-wal
1,278,920 places.sqlite-wal

fchash.exe --md5 t:\places.sqlite-wal
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal

file sizes of the copied files

dir d:\test

directory of d:\test\copied.by.dos
1,934,760 places.sqlite-wal

directory of d:\test\copied.by.doublecommander
1,934,760 places.sqlite-wal

directory of d:\test\copied.by.fastcopy
1,934,760 places.sqlite-wal

directory of d:\test\copied.by.powershell
1,934,760 places.sqlite-wal

directory of d:\test\copied.by.rclone
1,934,760 places.sqlite-wal

directory of d:\test\copied.by.windows.explorer
1,934,760 places.sqlite-wal

md5 hash of the copied files

fchash.exe --md5 --recursive d:\test
d:\test\copied.by.dos\ :
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal
d:\test\copied.by.doublecommander\ :
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal
d:\test\copied.by.fastcopy\ :
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal
d:\test\copied.by.powershell\ :
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal
d:\test\copied.by.rclone\ :
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal
d:\test\copied.by.windows.explorer\ :
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal

yichi_yang · October 11, 2023, 9:29pm

Thank you for the clarification. I think I see your point now. I'll do a bit more testing with other copy tools over the weekend.

Do you agree we indeed have the same problem (I'm referring to the one you reported here)?

Note I only run into problem when I try to rclone sync --filter-from:

But if I directly rclone sync \path\to\problematic_file, it works without problem:

(I might have missed it, but) when you mentioned rclone copy t:\ --include=filename in that other post, I think it behaves the same as your test above if you add --local-no-check-updated, correct?

asdffdsa · October 11, 2023, 10:34pm

sorry, not correct.
it is more complex than that, and what i was working on before.

now, we understand that corrupted on transfer: sizes differ is the expected output.
good that rclone complains.

but here is a problem. why does rclone NOT complain yet somehow copy the file same as other copy tools.

rclone.exe copy t:\places.sqlite-wal d:\test\copied.by.rclone\using.filename -vv --retries=1 
DEBUG : places.sqlite-wal: md5 = 0a4372a5baca1055cdd865c44b2c84b9 OK
INFO  : places.sqlite-wal: Copied (new)

and now, much worse problem. here rclone compains, i force it to copy the file.
seems to me, in this example, rclone does corrupt the file.

rclone.exe copy t:\ d:\test\copied.by.rclone\using.dir+include --include=places.sqlite-wal  --local-no-check-updated  -vv --retries=1
DEBUG : places.sqlite-wal: md5 = a980a1574c3b336f3bc8cd470b4f7e52 OK

ncw · October 11, 2023, 10:36pm

I made a small test which I'd like someone who is having troubles with volume shadow snapshots to try here

Download this https://pub.rclone.org/windows-shadow-bug.zip and unzip it. It has a Go program which will do a simple test. You'll find a windows binary and a linux binary. Give it the path to the troublesome file and run it. It should print something like this
> windows-shadow-bug.exe main.go
Testing "main.go"
Size read with os.Stat      : 814
Size read with os.File.Stat : 814
If that gives a different answer then that's enough for me to make report a Go bug, though I should try to replicate it first! If I can't replicate it then you could join me on the Go bug report and answer questions.

asdffdsa · October 11, 2023, 11:26pm

1278920 = source file size
1934760 = dest file size, as reported by dos, powershell, fastcopy and more.

note: the window os is changing the file during the copy operation.
so, rclone is correct and good to complain about corrupted on transfer: sizes differ

here is the results for the source.
i added the hash, as we will need when discussing the dest/copied files.

dir t:\places.sqlite-wal
10/08/2023  12:02 PM         1,278,920 places.sqlite-wal
               1 File(s)      1,278,920 bytes

rclone.exe lsl t:\places.sqlite-wal
  1278920 2023-10-08 12:02:46.472819900 places.sqlite-wal

fchash.exe --md5 t:\places.sqlite-wal
  md5 <0a4372a5baca1055cdd865c44b2c84b9>: places.sqlite-wal

rclone.exe md5sum t:\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9  places.sqlite-wal

windows-shadow-bug.exe t:\places.sqlite-wal 
Testing "t:\\places.sqlite-wal"
Size read with os.Stat      : 1934760
Size read with os.File.Stat : 1934760

asdffdsa · October 11, 2023, 11:50pm

@yichi_yang, sorry, this is your topic, you should reply to ncw?