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

Help and Support
21

I made a minimal reproducible example here: rclone_issue.7z - Google Drive (the password is rclone; I need to password protect the archive because Google Drive flags zips containing Python scripts).

Please see README.md in the archive for more information. If you run the example, you should see something like this:

PS C:\Users\Yichi\rclone_issue> py .\reproduce_issue.py

VSHADOW.EXE 3.0 - Volume Shadow Copy sample client.
Copyright (C) 2005 Microsoft Corporation. All rights reserved.

# Omitted a bunch of VSS related stuff

C:\Users\Yichi\rclone_issue>for /L %i in (1 1 3) do (
dir \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 C:\Users\Yichi\rclone_issue\windows-shadow-bug.exe \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 certutil -hashfile \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin MD5
 timeout 1
)

C:\Users\Yichi\rclone_issue>(
dir \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 C:\Users\Yichi\rclone_issue\windows-shadow-bug.exe \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 certutil -hashfile \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin MD5
 timeout 1
)
The filename, directory name, or volume label syntax is incorrect.
Testing "\\\\?\\GLOBALROOT\\Device\\HarddiskVolumeShadowCopy140\\Users\\Yichi\\rclone_issue\\test_src\\test.bin"
Size read with os.Stat      : 142
Size read with os.File.Stat : 142
MD5 hash of \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin:
94cde25ecffd3f73240f3d83ffd6b5e4
CertUtil: -hashfile command completed successfully.

Waiting for 0 seconds, press a key to continue ...

C:\Users\Yichi\rclone_issue>(
dir \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 C:\Users\Yichi\rclone_issue\windows-shadow-bug.exe \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 certutil -hashfile \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin MD5
 timeout 1
)
The filename, directory name, or volume label syntax is incorrect.
Testing "\\\\?\\GLOBALROOT\\Device\\HarddiskVolumeShadowCopy140\\Users\\Yichi\\rclone_issue\\test_src\\test.bin"
Size read with os.Stat      : 142
Size read with os.File.Stat : 142
MD5 hash of \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin:
94cde25ecffd3f73240f3d83ffd6b5e4
CertUtil: -hashfile command completed successfully.

Waiting for 0 seconds, press a key to continue ...

C:\Users\Yichi\rclone_issue>(
dir \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 C:\Users\Yichi\rclone_issue\windows-shadow-bug.exe \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin
 certutil -hashfile \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin MD5
 timeout 1
)
The filename, directory name, or volume label syntax is incorrect.
Testing "\\\\?\\GLOBALROOT\\Device\\HarddiskVolumeShadowCopy140\\Users\\Yichi\\rclone_issue\\test_src\\test.bin"
Size read with os.Stat      : 142
Size read with os.File.Stat : 142
MD5 hash of \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin:
94cde25ecffd3f73240f3d83ffd6b5e4
CertUtil: -hashfile command completed successfully.

Waiting for 0 seconds, press a key to continue ...

C:\Users\Yichi\rclone_issue>rclone copy \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin C:\Users\Yichi\rclone_issue\test_dst\rclone_file\

C:\Users\Yichi\rclone_issue>dir C:\Users\Yichi\rclone_issue\test_dst\rclone_file\test.bin
 Volume in drive C has no label.
 Volume Serial Number is 00B2-AADC

 Directory of C:\Users\Yichi\rclone_issue\test_dst\rclone_file

2023/10/11  20:37               142 test.bin
               1 File(s)            142 bytes
               0 Dir(s)  217,217,105,920 bytes free

C:\Users\Yichi\rclone_issue>certutil -hashfile C:\Users\Yichi\rclone_issue\test_dst\rclone_file\test.bin MD5
MD5 hash of C:\Users\Yichi\rclone_issue\test_dst\rclone_file\test.bin:
94cde25ecffd3f73240f3d83ffd6b5e4
CertUtil: -hashfile command completed successfully.

C:\Users\Yichi\rclone_issue>rclone copy \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src C:\Users\Yichi\rclone_issue\test_dst\rclone_directory\
2023/10/11 20:37:44 NOTICE: test.bin.jovagef2.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 ERROR : test.bin: Failed to copy: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 ERROR : Attempt 1/3 failed with 1 errors and: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 NOTICE: test.bin.heyehip2.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 ERROR : test.bin: Failed to copy: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 ERROR : Attempt 2/3 failed with 1 errors and: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 NOTICE: test.bin.rinarez4.partial: Removing partially written file on error: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 ERROR : test.bin: Failed to copy: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 ERROR : Attempt 3/3 failed with 1 errors and: can't copy - source file is being updated (size changed from 133 to 142)
2023/10/11 20:37:44 Failed to copy: can't copy - source file is being updated (size changed from 133 to 142)

C:\Users\Yichi\rclone_issue>dir C:\Users\Yichi\rclone_issue\test_dst\rclone_directory\test.bin
 Volume in drive C has no label.
 Volume Serial Number is 00B2-AADC

 Directory of C:\Users\Yichi\rclone_issue\test_dst\rclone_directory

File Not Found

C:\Users\Yichi\rclone_issue>if not exist C:\Users\Yichi\rclone_issue\test_dst\copy mkdir C:\Users\Yichi\rclone_issue\test_dst\copy

C:\Users\Yichi\rclone_issue>copy /Y \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy140\Users\Yichi\rclone_issue\test_src\test.bin C:\Users\Yichi\rclone_issue\test_dst\copy\
        1 file(s) copied.

C:\Users\Yichi\rclone_issue>dir C:\Users\Yichi\rclone_issue\test_dst\copy\test.bin
 Volume in drive C has no label.
 Volume Serial Number is 00B2-AADC

 Directory of C:\Users\Yichi\rclone_issue\test_dst\copy

2023/10/11  20:37               142 test.bin
               1 File(s)            142 bytes
               0 Dir(s)  217,217,105,920 bytes free

C:\Users\Yichi\rclone_issue>certutil -hashfile C:\Users\Yichi\rclone_issue\test_dst\copy\test.bin MD5
MD5 hash of C:\Users\Yichi\rclone_issue\test_dst\copy\test.bin:
94cde25ecffd3f73240f3d83ffd6b5e4
CertUtil: -hashfile command completed successfully.
-----------------------------------------------------

Snapshot creation done.

Basically what happens is the script will continuously write to a file, and at the same time try to create a VSS snapshot and rclone copy from the snapshot.

A few observations:

  1. The MD5 hash of the file in the snapshot doesn't change if we check a few times (waiting 1s in between). I think at this point we can say with some confidence that the file indeed isn't changing in the snapshot. For some reason dir doesn't work for files in the snapshot (the filename, directory name, or volume label syntax is incorrect.).
  2. windows-shadow-bug.exe consistently reports the same size (os.Stat and os.File.Stat report the same number).
  3. rclone copy \somewhere\in\snapshot\test.bin \path\to\destination works and the destination file has the correct hash.
  4. rclone copy \somewhere\in\snapshot\parent_directory \path\to\destination doesn't work and complain about source file is being updated
  5. The copy command behaves mostly the same as 3 (works, correct hash).
22

Thank you @asdffdsa and @yichi_yang for trying windows-shadow-bug.exe.

That is a great example - thank you. I will try it out shortly.

That is agrees with my analysis of the rclone logs. The File is OK and reads fine.

Disappointing but maybe the update will show different numbers (see below).

The difference between these is that the file length in the first one will be read with Stat directly and in the second we get it from the directory listing.

That makes me think I need another check in windows-shadow-bug.exe to get the Stat block from the listing (which is what rclone does at the start) and then it uses os.File.Stat to check it just before transfer.

Can you re-download it from here: https://pub.rclone.org/windows-shadow-bug.zip - it should print more lines now

> windows-shadow-bug.exe c:\go\src\github.com\rclone\rclone\README.md 
Testing "c:\go\src\github.com\rclone\rclone\README.md"
Listing "c:\go\src\github.com\rclone\rclone" looking for "README.md"
Size read with os.Stat      : 8939
Size read with os.Lstat     : 8939
Size read with os.File.Stat : 8939  <- this is what rclone reads second
Size read with f.Readdir    : 8939  <- this is what rclone reads first
23

here is the output using the same vss snapshot as before, so the values are the same:
1278920 is the size of the source file.
1934760 is the size of the dest flie.

windows-shadow-bug.exe t:\places.sqlite-wal 
Testing "t:\\places.sqlite-wal"
Listing "t:\\" looking for "places.sqlite-wal"
Size read with os.Stat      : 1934760
Size read with os.Lstat     : 1934760
Size read with os.File.Stat : 1934760
Size read with f.Readdir    : 1278920
*** File size mismatch!!! ***
24

Ah, ha - a difference!

What do you mean by the source and dest file? These should all refer to the same file t:\places.sqlite-wal shouldn't they?

I was unable to install vshadow.exe - it doesn't seem to be part of the Windows debugging tools under Windows 10 which I am confused about! I did manage to make a shadow volume which I manually mounted but I haven't managed to replicate the problem yet.

25

well, with rclone copy, there is a source file and a dest/copied file.
t:\places.sqlite-wal is the source file.

1278920 is the size of t:\places.sqlite-wal, every tool i have tested confirms that.

from my wiki
"Vshadow.exe is part of the Window SDK which can be download free from Micro$oft at Windows SDK - Windows app development | Microsoft Developer. You will have to install the SDK and search for vshadow.exe"

here it is. no need for the SDK
https://s3.us-east-2.wasabisys.com/zork/vshadow.exe

you can follow my wiki, only step 1 and step 2 is required.
bascailly, only three lines of dumb dos code to create the snapshot.

in all my posts, to make debugging easier, i do the additional, optional step of variant #1.
"You may find it less confusing if you create an alias t: that you can use when referring to the snapshot:"

and you need to find the right file to test,
need a file that will cause rclone to output corrupted on transfer: sizes differ
so go hunting for the file inside the user's appdata dir - C:\Users\%username%\AppData

26

for dir to work, can implement variant #1 from my wiki.

mklink /D b:\rclone\vss\system\ \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy52\ 
symbolic link created for b:\rclone\vss\system\ <<===>> \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy52\

dir B:\rclone\vss\system\Users\user01\AppData\Roaming\Thunderbird\Profiles\idsc7o79.default-release\places.sqlite-wal
10/08/2023  12:02 PM         1,278,920 places.sqlite-wal

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

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

I caught one!

I mounted my shadow at "C:\shadow"

I followed your advice and used rclone copy to copy everything out of AppData until I found a file which was misbehaving.

C:\>windows-shadow-bug.exe C:\shadow\Users\Dev\AppData\Local\Temp\43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp
Testing "C:\\shadow\\Users\\Dev\\AppData\\Local\\Temp\\43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp"
Listing "C:\\shadow\\Users\\Dev\\AppData\\Local\\Temp" looking for "43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp"
Size read with os.Stat      : 3930134
Size read with os.Lstat     : 3930134
Size read with os.File.Stat : 3930134
Size read with f.Readdir    : 3628053
*** File size mismatch!!! ***

Comparing the file in the shadow volume vs the real file it is clear that the Stat calls are reading the size of the real file, but the directory listing is reading the size of the shadow file as we expect.

C:\>dir C:\shadow\Users\Dev\AppData\Local\Temp\43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp
 Volume in drive C has no label.
 Volume Serial Number is 464C-ABA7

 Directory of C:\shadow\Users\Dev\AppData\Local\Temp

12/10/2023  13:00         3,628,053 43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp
               1 File(s)      3,628,053 bytes
               0 Dir(s)   3,088,945,152 bytes free

C:\>dir C:\Users\Dev\AppData\Local\Temp\43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp
 Volume in drive C has no label.
 Volume Serial Number is 464C-ABA7

 Directory of C:\Users\Dev\AppData\Local\Temp

12/10/2023  14:22         3,930,134 43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp
               1 File(s)      3,930,134 bytes
               0 Dir(s)     397,148,160 bytes free

C:\>

The go runtime uses GetFileAttributesEx for these stat calls.

I thought I try this in powershell and it seems to give the wrong answer always. Even dir gives the wrong answer in powershell but the right answer in cmd.

So I'm utterly confused now!

Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.

Try the new cross-platform PowerShell https://aka.ms/pscore6

PS C:\WINDOWS\system32> c:
PS C:\WINDOWS\system32> cd
PS C:\WINDOWS\system32> cd \
PS C:\>  dir C:\shadow\Users\Dev\AppData\Local\Temp\43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp


    Directory: C:\shadow\Users\Dev\AppData\Local\Temp


Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
-a----        12/10/2023     12:59        3930134 43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp


PS C:\>  $File = Get-Item C:\shadow\Users\Dev\AppData\Local\Temp\43c24beb-53f9-40e4-a1ed-e72cf497e38e.tmp
PS C:\> $File.length
3930134
PS C:\>

Any ideas? Can anyone see any documentation about this anywhere?

28

Spent some time Googling but that didn't help. I have no clue about the Windows API side of things. I guess I'll leave that to someone with more experience with VSS / Windows APIs.

29

tl;dr - it occurred to me that restic using go lang; so i tested it.
it produces the same/correct filesize, md5 hash and modtime, as the other copy tools
maybe that will spark an idea?

as for restic,
i used this command for backup

restic backup t:\places.sqlite-wal --compression=off --verbose --no-cache

here is the contents of the repo:
notice that the filesize and modtime are same/correct as compared to the other copy tools.

restic ls --long 7e662025 
debug log file .\restic.log
debug enabled
snapshot 7e662025 of [t:\places.sqlite-wal] filtered by [] at 2023-10-12 15:06:30.9902901 -0400 EDT):
drwxrwxrwx     0     0      0 2023-10-10 15:06:06 /t
-rw-rw-rw-     0     0 1934760 2023-10-10 12:47:58 /t/places.sqlite-wal

i used this command to restore the file from restic repo

restic restore --target=d:\test\copied.by.restic 7e662025  
debug log file .\restic.log
debug enabled
restoring <Snapshot 7e662025 of [t:\places.sqlite-wal] at 2023-10-12 15:06:30.9902901 -0400 EDT by EN10\user01@EN10> to d:\test\copied.by.restic
Summary: Restored 2 Files (1.845 MiB) in 0:00

and now, i re-run the same restic backup command again, what will restic do?
if i read this correctly, restic considers the source file and the dest file in the repo to be the same, will not re-copy it

restic backup t:\places.sqlite-wal --compression=off --verbose --no-cache 
using parent snapshot 7e662025
load index files
start scan on [t:\places.sqlite-wal]
start backup on [t:\places.sqlite-wal]
scan finished in 0.234s: 1 files, 1.845 MiB

Files:           0 new,     0 changed,     1 unmodified
Dirs:            0 new,     0 changed,     1 unmodified
Data Blobs:      0 new
Tree Blobs:      0 new
Added to the repository: 0 B   (0 B   stored)

processed 1 files, 1.845 MiB in 0:00
snapshot e8977095 saved

now here is all the raw data.

this is the info on the source file t:\places.sqlite-wal

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

certutil -hashfile t:\places.sqlite-wal MD5
MD5 hash of t:\places.sqlite-wal:
0a4372a5baca1055cdd865c44b2c84b9

and i checked the hashes of all the dest/copied files.
notice that rclone calculates two different md5 hash values

a980a1574c3b336f3bc8cd470b4f7e52 *copied.by.rclone\using.dir+include\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.rclone\using.filename\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.windows.explorer\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.restic\t\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.doublecommander\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.dos\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.powershell\places.sqlite-wal
0a4372a5baca1055cdd865c44b2c84b9 *copied.by.fastcopy\places.sqlite-wal

and i checked all the file sizes and modtimes.
notice that rclone calculates two different file sizes and two different modtimes.

c:\data\rclone>dir /s d:\test

directory of d:\test\copied.by.dos
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal
               1 File(s)      1,934,760 bytes

directory of d:\test\copied.by.doublecommander
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal

directory of d:\test\copied.by.fastcopy
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal

directory of d:\test\copied.by.powershell
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal

directory of d:\test\copied.by.rclone\using.dir+include
10/08/2023  12:02 PM         1,278,920 places.sqlite-wal

directory of d:\test\copied.by.rclone\using.filename
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal

directory of d:\test\copied.by.restic\t
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal

directory of d:\test\copied.by.windows.explorer
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal
30

fwiw, i still think this is not really a vss issue, that it is not really relevant.
as corrupted on transfer: sizes differ happens to most any file system on most any operating system.

perhaps nobody every really look into that.

we would need a way to re-produce and maybe tricky to do.
as, in this case, vss makes it easy to investigate.
would be nice, if we can create a test, on a more normal file system, might even work on linux.
and stop with the added complexity of vss and to make it easier for you test on your local linux/windows system

ncw, not sure you read this from up above?

below, the first rclone command works, as the other copy tools do.
--- the same filesize, the same, md5 hash, the same modtime
--- rclone does not complain about corrupted on transfer: sizes differ
and worth noting, the other tools also do not complain.

the second rclone command does not work, as the other copy tools.
--- rclone corrupts the filesize, md5 hash, modtime.
--- rclone does complain about `corrupted on transfer: sizes differ

--- the same filesize, the same md5 hash, the s

31

This is the cause of the problem, undoubtedly. One Windows API (the directory listing API) is giving the correct size of the file, whereas the other (the GetFileAttributesEx) is giving the wrong size.

This could be

  1. A bug in the Go runtime
  2. A bug in Windows Volume Shadow implementation
  3. The expected way that Windows Volume Shadows work.

Which of those is the case I do not know!

I can eliminate 1. by writing a C or maybe a Python program - if it gives the same answer as the Go program then we know it is 2 or 3. If not then it must be 1.

I suspect 1. or 2. because it doesn't do this all the time. Sometimes it returns the correct answer when the shadow file and the underlying file are different and sometimes it returns the wrong answer.

This issue does reproduce with python

# Stat a file
import os
import sys

file_name = sys.argv[1]
fi = os.stat(file_name)
print(f"size of {file_name} from python {fi.st_size}")

Call this python stat.py path\to\file and it will do what rclone does, stat the file and get the same wrong answer.

@asdffdsa and @yichi_yang can you veryify that?

32

This is what I got:

C:\Users\Yichi\Documents\rclone_issue>C:\Users\Yichi\Documents\rclone_issue\windows-shadow-bug.exe \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy146\Users\Yichi\Documents\rclone_issue\test_src\test.bin
Testing "\\\\?\\GLOBALROOT\\Device\\HarddiskVolumeShadowCopy146\\Users\\Yichi\\Documents\\rclone_issue\\test_src\\test.bin"
Listing "\\\\?\\GLOBALROOT\\Device\\HarddiskVolumeShadowCopy146\\Users\\Yichi\\Documents\\rclone_issue\\test_src" looking for "test.bin"
Size read with os.Stat      : 103
Size read with os.Lstat     : 103
Size read with os.File.Stat : 103
Size read with f.Readdir    : 102
*** File size mismatch!!! ***

C:\Users\Yichi\Documents\rclone_issue>py C:\Users\Yichi\Documents\rclone_issue\get_size.py \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy146\Users\Yichi\Documents\rclone_issue\test_src\test.bin
size of \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy146\Users\Yichi\Documents\rclone_issue\test_src\test.bin from python 103
33

thanks, here is the output.
1934760 - that is the size of the windows os modified source file
the same file size as all other copy tools output, including restic.

size of t:\places.sqlite-wal from python 1934760
34

That shows that python is giving the same wrong answer. So this isn't a go specific problem.

That's the destination size isn't it, so the wrong size as we are expecting the source size on t:\ aren't we?

I probably need to put a workaround for this in rclone. I wonder if it's easy to detect we are copying from a volume shadow.

35

I tried restic with VSS a long time ago and I vaguely recall it worked (at least it appeared to work; I'm not sure if it has the same hash / size check like rclone does). I did briefly went over the relevant source code a while back and I believe restic interfaces with VSS by making syscalls directly. Just my two cents - would it be better (cleaner, more robust, more flexible) if rclone do something similar (i.e., interface with VSS directly and add a --local-use-fs-snapshot swtich to control that feature)? Obviously it's gonna require a significant amount of work, but if that's something we want to consider, maybe we should put it on the road map so people can contribute (i.e., open to PRs)?

36

maybe think that there are two source files.

  1. 1,278,920 - the original file size in the vss snapshot.
  2. 1,934,760 - when you try to copy that source file, windows os changes the size.

#1 - none of the copy tools use that
#2 - what all the other copy tools use, including restic.

correct - behaves as all the other copy tools, i keep posting about.
so python is correct, as restic is correct and fastcopy are correct and all the other tools i posted about.
1,934,760 is correct

correct

rclone.exe copy t:\places.sqlite-wal d:\test\copied.by.rclone\using.filename

directory of d:\test\copied.by.rclone\using.filename
10/10/2023  12:47 PM         1,934,760 places.sqlite-wal

not correct

rclone.exe copy t:\ d:\test\copied.by.rclone\using.dir+include --include=places.sqlite-wal  --local-no-check-updated`

directory of d:\test\copied.by.rclone\using.dir+include
10/08/2023  12:02 PM         1,278,920 places.sqlite-wal
37

i posted a detailed example up above, where restic behaves as correct, as expected.
in that case, not using --local-use-fs-snapshot, to better mimic all ther other tools i have tested.

maybe now, i am going to test --local-use-fs-snapshot and see what restic does.

for me, that is not useful, as my backup script creates one snapshot and run rclone, 7z, fastcopy and so on.

Possible to copy open files on Windows with VSS?

38

This makes me think that I am mis-understanding something!

You say the original size in the vss snapshot is 1,278,920. So when you dir t:\places.sqlite-wal you get1,278,920 - I see this in your test from above.

But when you copy it (not with rclone) it becomes 1,934,760 bytes which is actually the size of the underlying file. So apparently a file has changed in the snapshot!

That sounds like the snapshot isn't working to me or maybe I have mis-understood exactly what the volume shadows do. My mental model is that they are like LVM snapshots - you get exactly what was on the drive at the moment of the snapshot forever, but they don't seem to be working like that.

In my worldview 1,278,920 should be the size of the file as that is what the size lists as in the shadow and when you copy it, it should be that big too. How do you explain the file changing size to 1,934,760 bytes?

Please unconfuse me :slight_smile:

Anyway this is easy to fix for rclone - we just need to stat the file before opening it to update the file size. This will also reduce the frequency of the "can't copy - source file is being updated" errors when they aren't needed.

v1.65.0-beta.7431.1fc84023a.fix-windows-vss on branch fix-windows-vss (uploaded in 15-30 mins)

39

correct

correct

i do not explain it. just that rclone should behave same as the other copy tools

well, the beta is a good step forward, but rclone continues to corrupt.

sorry for the confusion, but i had to use a new vss snapshot. as a result, the filesize and md5 hash changed.

dir t:\places.sqlite-wal  
10/12/2023  06:02 PM           885,416 places.sqlite-wal 

fchash --md5  t:\places.sqlite-wal  
md5 <5758a9157a7954a1e6416bf7582bac1f>: places.sqlite-wal

as for the beta,

#1 - as before, this command works as expected. the beta did not change that.

rclone copy t:\places.sqlite-wal  d:\test\beta\copied.by.rclone\using.filename
DEBUG : rclone: Version "v1.65.0-beta.7431.1fc84023a.fix-windows-vss" starting with parameters ["d:\\data\\rclone\\exe\\windows\\rclone-v1.65.0-beta.7431.1fc84023a.fix-windows-vss-windows-amd64\\rclone.exe" "copy" "t:\\places.sqlite-wal " "d:\\test\\beta\\copied.by.rclone\\using.filename" "-vv" "--retries=1"]
DEBUG : places.sqlite-wal : md5 = 5758a9157a7954a1e6416bf7582bac1f OK

#2 - this is an big improvement.
--- file size, md5 hash and modtime - match all the other copy tools.
--- no longer errors out with corrupted on transfer: sizes differ

rclone copy t:\ d:\test\beta\copied.by.rclone\using.dir+include\1 --include=places.sqlite-wal 
DEBUG : rclone: Version "v1.65.0-beta.7431.1fc84023a.fix-windows-vss" starting with parameters ["d:\\data\\rclone\\exe\\windows\\rclone-v1.65.0-beta.7431.1fc84023a.fix-windows-vss-windows-amd64\\rclone.exe" "copy" "t:\\" "d:\\test\\beta\\copied.by.rclone\\using.dir+include\\1" "--include=places.sqlite-wal " "-vv" "--retries=1"]
DEBUG : places.sqlite-wal : md5 = 5758a9157a7954a1e6416bf7582bac1f OK

#3, as before, rclone continue to corrupt the file

rclone copy t:\ d:\test\beta\copied.by.rclone\using.dir+include\2 --include=places.sqlite-wal  --local-no-check-updated 
DEBUG : rclone: Version "v1.65.0-beta.7431.1fc84023a.fix-windows-vss" starting with parameters ["d:\\data\\rclone\\exe\\windows\\rclone-v1.65.0-beta.7431.1fc84023a.fix-windows-vss-windows-amd64\\rclone.exe" "copy" "t:\\" "d:\\test\\beta\\copied.by.rclone\\using.dir+include\\2" "--include=places.sqlite-wal " "-vv" "--retries=1" "--local-no-check-updated"]
DEBUG : places.sqlite-wal : md5 = a2510674c18f4b4d355bc4326fe6bbcf OK
40

Looks like we are getting there!

You shouldn't need that any more. I'm not sure why it is causing a problem though - I will investigate.