Wrong error?: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes

Viper · June 9, 2024, 9:00am

Hello, I'm using rclone with DigiStorage and GoogleDrive, both mounted as network drives, --vfs-cache-mode off, but when writing a file to any of these two mounts I can see this error (from the subject) in the logs, yet the file gets written successfully.

rclone v1.66.0
- os/version: Microsoft Windows 11 Education 23H2 (64 bit)
- os/kernel: 10.0.22631.3447 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.22.1
- go/linking: static
- go/tags: cmount

WinFsp 2023 (2.0.23075)

[DigiStorage]
type = koofr
provider = digistorage
user = XXX
password = XXX
description = DigiStorage

[GoogleDrive]
type = drive
client_id = XXX
client_secret = XXX
scope = drive
token = XXX
team_drive =

For the mounts I'm using:

rclone mount "DigiStorage:" X: -v --poll-interval 0 --network-mode
rclone mount "GoogleDrive:" Y: -v --network-mode --drive-chunk-size 64M

And a redacted log catching the error:

11:44:01 DEBUG : /test/100MB.bin: CreateEx: flags=0x502, mode=0700
11:44:01 DEBUG : test/100MB.bin: Open: flags=O_RDWR|O_CREATE|O_EXCL
11:44:01 DEBUG : test: Added virtual directory entry vAddFile: "100MB.bin"
11:44:01 DEBUG : test/100MB.bin: >Open: fd=test/100MB.bin (w), err=<nil>
11:44:01 DEBUG : /test/100MB.bin: >CreateEx: errc=0, fh=0x0
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test/100MB.bin: Getpath: Getpath fh=0
11:44:01 DEBUG : /test/100MB.bin: >Getpath: errc=0, normalisedPath="/test/100MB.bin"
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:01 DEBUG : /test: >Getattr: errc=0
11:44:01 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:01 DEBUG : /test: >Getattr: errc=0
11:44:01 DEBUG : /test: Opendir:
11:44:01 DEBUG : /test: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:01 DEBUG : /test: >OpenFile: fd=test/ (r), err=<nil>
11:44:01 DEBUG : /test: >Opendir: errc=0, fh=0x2
11:44:01 DEBUG : /test: Getpath: Getpath fh=2
11:44:01 DEBUG : /test: >Getpath: errc=0, normalisedPath="/test"
11:44:01 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:01 DEBUG : /test: >Getattr: errc=0
11:44:01 DEBUG : /test: Releasedir: fh=0x2
11:44:01 DEBUG : /test: >Releasedir: errc=0
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test/100MB.bin: Chmod: mode=0666
11:44:01 DEBUG : /test/100MB.bin: >Chmod: errc=0
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test/100MB.bin: Truncate: size=104857600, fh=0x0
11:44:01 ERROR : test/100MB.bin: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes
11:44:01 DEBUG : /test/100MB.bin: >Truncate: errc=-1
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test/100MB.bin: Write: ofst=0, fh=0x0
11:44:01 DEBUG : test: Added virtual directory entry vAddFile: "100MB.bin"
11:44:01 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test/100MB.bin: Write: ofst=1048576, fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:01 DEBUG : /test/100MB.bin: Write: ofst=2097152, fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:01 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:01 DEBUG : /test/100MB.bin: >Getattr: errc=0
[...]
11:44:02 DEBUG : /test/100MB.bin: Write: ofst=69206016, fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:02 DEBUG : /test/100MB.bin: Write: ofst=70254592, fh=0x0
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:02 DEBUG : /test/100MB.bin: OpenEx: flags=0x0
11:44:02 DEBUG : /test/100MB.bin: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:02 DEBUG : test/100MB.bin: Open: flags=O_RDONLY
11:44:02 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:02 DEBUG : /test/100MB.bin: Write: ofst=71303168, fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
[...]
11:44:02 DEBUG : /test/100MB.bin: Write: ofst=103809024, fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Write: n=1048576
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Opendir:
11:44:02 DEBUG : /test: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:02 DEBUG : /test: >OpenFile: fd=test/ (r), err=<nil>
11:44:02 DEBUG : /test: >Opendir: errc=0, fh=0x2
11:44:02 DEBUG : /test: Getpath: Getpath fh=2
11:44:02 DEBUG : /test: >Getpath: errc=0, normalisedPath="/test"
11:44:02 DEBUG : /test: Releasedir: fh=0x2
11:44:02 DEBUG : /test: >Releasedir: errc=0
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Opendir:
11:44:02 DEBUG : /test: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:02 DEBUG : /test: >OpenFile: fd=test/ (r), err=<nil>
11:44:02 DEBUG : /test: >Opendir: errc=0, fh=0x2
11:44:02 DEBUG : /test: Getpath: Getpath fh=2
11:44:02 DEBUG : /test: >Getpath: errc=0, normalisedPath="/test"
11:44:02 DEBUG : /test: Releasedir: fh=0x2
11:44:02 DEBUG : /test: >Releasedir: errc=0
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:02 DEBUG : /test/100MB.bin: Utimens: tmsp=[{Sec:1717922642 Nsec:839114900} {Sec:1717922613 Nsec:358296000}]
11:44:02 DEBUG : /test/100MB.bin: Utimens: SetModTime: 2024-06-09 11:43:33.358296 +0300 EEST
11:44:02 DEBUG : /test/100MB.bin: >Utimens: errc=0
11:44:02 DEBUG : /test/100MB.bin: Getattr: fh=0x0
11:44:02 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:02 DEBUG : /test/100MB.bin: Flush: fh=0x0
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Opendir:
11:44:02 DEBUG : /test: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:02 DEBUG : /test: >OpenFile: fd=test/ (r), err=<nil>
11:44:02 DEBUG : /test: >Opendir: errc=0, fh=0x2
11:44:02 DEBUG : /test: Getpath: Getpath fh=2
11:44:02 DEBUG : /test: >Getpath: errc=0, normalisedPath="/test"
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Readdir: ofst=0, fh=0x2
11:44:02 DEBUG : /test: >Readdir: items=1, errc=0
11:44:02 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /: >Getattr: errc=0
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Releasedir: fh=0x2
11:44:02 DEBUG : /test: >Releasedir: errc=0
11:44:02 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /: >Getattr: errc=0
11:44:02 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /: >Getattr: errc=0
11:44:02 DEBUG : /: Opendir:
11:44:02 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:02 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
11:44:02 DEBUG : /: >Opendir: errc=0, fh=0x2
11:44:02 DEBUG : /: Getpath: Getpath fh=2
11:44:02 DEBUG : /: >Getpath: errc=0, normalisedPath=""
11:44:02 DEBUG : /: Statfs:
11:44:02 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:1315962880 Bfree:461503744 Bavail:461503744 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
11:44:02 DEBUG : /: Releasedir: fh=0x2
11:44:02 DEBUG : /: >Releasedir: errc=0
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:02 DEBUG : /test: >Getattr: errc=0
11:44:02 DEBUG : /test: Opendir:
11:44:02 DEBUG : /test: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:02 DEBUG : /test: >OpenFile: fd=test/ (r), err=<nil>
11:44:02 DEBUG : /test: >Opendir: errc=0, fh=0x2
11:44:02 DEBUG : /test: Getpath: Getpath fh=2
11:44:02 DEBUG : /test: >Getpath: errc=0, normalisedPath="/test"
11:44:02 DEBUG : /test: Releasedir: fh=0x2
11:44:02 DEBUG : /test: >Releasedir: errc=0
11:44:02 DEBUG : /test: Releasedir: fh=0x1
11:44:02 DEBUG : /test: >Releasedir: errc=0
11:44:04 DEBUG : test/100MB.bin: md5 = 56e3dd7dce6c2eb592c8b280326d2c5b OK
11:44:04 DEBUG : test/100MB.bin: Size and md5 of src and dst objects identical
11:44:04 DEBUG : test: Added virtual directory entry vAddFile: "100MB.bin"
11:44:04 DEBUG : /test/100MB.bin: >Flush: errc=0
11:44:04 DEBUG : /test/100MB.bin: Release: fh=0x0
11:44:04 DEBUG : test/100MB.bin: WriteFileHandle.Release nothing to do
11:44:04 DEBUG : /test/100MB.bin: >Release: errc=0
11:44:04 DEBUG : test/100MB.bin: >Open: fd=test/100MB.bin (r), err=<nil>
11:44:04 DEBUG : /test/100MB.bin: >OpenFile: fd=test/100MB.bin (r), err=<nil>
11:44:04 DEBUG : /test/100MB.bin: >OpenEx: errc=0, fh=0x0
11:44:04 DEBUG : /test/100MB.bin: Getpath: Getpath fh=0
11:44:04 DEBUG : /test/100MB.bin: >Getpath: errc=0, normalisedPath="/test/100MB.bin"
11:44:04 DEBUG : /test/100MB.bin: Flush: fh=0x0
11:44:04 DEBUG : /test/100MB.bin: >Flush: errc=0
11:44:04 DEBUG : /test/100MB.bin: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:04 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:04 DEBUG : /test/100MB.bin: Release: fh=0x0
11:44:04 DEBUG : /test/100MB.bin: >Release: errc=0
11:44:04 DEBUG : /test/100MB.bin: Getattr: fh=0xFFFFFFFFFFFFFFFF
11:44:04 DEBUG : /test/100MB.bin: >Getattr: errc=0
11:44:04 DEBUG : /test/100MB.bin: OpenEx: flags=0x0
11:44:04 DEBUG : /test/100MB.bin: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
11:44:04 DEBUG : test/100MB.bin: Open: flags=O_RDONLY
11:44:04 DEBUG : test/100MB.bin: >Open: fd=test/100MB.bin (r), err=<nil>
11:44:04 DEBUG : /test/100MB.bin: >OpenFile: fd=test/100MB.bin (r), err=<nil>
11:44:04 DEBUG : /test/100MB.bin: >OpenEx: errc=0, fh=0x0
11:44:04 DEBUG : /test/100MB.bin: Getpath: Getpath fh=0
11:44:04 DEBUG : /test/100MB.bin: >Getpath: errc=0, normalisedPath="/test/100MB.bin"
11:44:04 DEBUG : /test/100MB.bin: Flush: fh=0x0
11:44:04 DEBUG : /test/100MB.bin: >Flush: errc=0
11:44:04 DEBUG : /test/100MB.bin: Release: fh=0x0
11:44:04 DEBUG : /test/100MB.bin: >Release: errc=0

a dir in the folder containing the 100MB.bin file locally:

104,857,600 100MB.bin

Is this a bug?
I went through every similar topic to this one but they all seem unsolved and closed for inactivity.
Probably related: Clarification on vfs-cache modes / O_APPEND O_TRUNC - #2 by ncw
Thank you!

asdffdsa · June 9, 2024, 12:49pm

welcome to the forum,

about the source and dest file, do they have the exact
--- file size
--- checksum

Viper · June 9, 2024, 12:53pm

Yes, the log posted above reflects that:

And I've checked myself again, now, and yes they end up to be the same.

asdffdsa · June 9, 2024, 1:38pm

i did some quick testing, i can replicate the issue.

to catch the attention of the authors, might be best to create a github issue.
and post the weblink into this topic.

system · July 9, 2024, 1:39pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.