Rclone 1.55 doesn't save file changes if the file has been reopened during upload (google drive mount)

Kirill · April 19, 2021, 5:10pm

What is the problem you are having with rclone?

I have a google drive mount, which is used then as a Samba share. There is MS Access DB, file size is ~ 205 Mb, it takes around 30 sec for rclone to upload it into google drive.
The case is the following:

The file is opened by a user via Samba (I believe Samba presens doesn't matter but anyway)
The user changes the file and closes it at a moment
Rclone starts upload to Google drive in 5 sec
As I mentioned above the upload takes ~ 30 sec
But the user re-opens the file in 15 sec (the file is being uploaded at that moment and the upload is not yet finished)
On file re-open attempt rclone checks remote fingerprint and somehow it is newer than vfs, so rclone removes vfs cache and downloads the remote version of the file. As a result the user looses his changes, as it was in vfs cache and not yet in a cloud:

2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: >Remove: err=<nil>
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: vfs cache: starting upload
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: Sending chunk 0 length 214302720
...
2021/04/19 19:31:55 DEBUG : TEST/: Lookup: name="test_DB.accdb"
2021/04/19 19:31:55 DEBUG : TEST/: >Lookup: node=TEST/test_DB.accdb, err=<nil>
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: Attr:
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=OpenReadOnly+0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=O_RDONLY|0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: newRWFileHandle:
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >newRWFileHandle: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fd=TEST/test_DB.accdb (rw), err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fh=&{TEST/test_DB.accdb (rw)}, err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: Flush:
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): RWFileHandle.Flush
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: >Flush: err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: Release:
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): RWFileHandle.Release
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): close:
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Applied pending mod time 2021-04-19 19:31:50.543320731 +0300 MSK OK
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): >close: err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: >Release: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=OpenReadWrite+0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=O_RDWR|0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: newRWFileHandle:
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >newRWFileHandle: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fd=TEST/test_DB.accdb (rw), err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fh=&{TEST/test_DB.accdb (rw)}, err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: Read: len=131072, offset=0
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc001956280): _readAt: size=131072, off=0
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc001956280): openPending:
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: checking remote fingerprint "214302720,2021-04-19 16:31:50.543 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25" ag
ainst cached fingerprint "214302720,2021-04-19 16:31:20.337 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25"
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: removing cached entry as stale (remote fingerprint "214302720,2021-04-19 16:31:50.543 +0000 UTC,870e2168a76dd
ae8c4e6edcde2316a25" != cached fingerprint "214302720,2021-04-19 16:31:20.337 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25")
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: cancelling writeback (uploading true) 0xc00012d110 item 492
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: cancelling upload
2021/04/19 19:31:56 ERROR : TEST/test_DB.accdb: Failed to copy: Post "****googleapis***/upload/drive/v3/files/1tgyX1lmZ_vxZgax332ufMYeMtWXi2GjE?alt=json&fields
=id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CexplicitlyTrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails%2CexportLinks&setModifie
dDate=true&supportsAllDrives=true&uploadType=resumable&upload_id=ABg5-UxS-tEA5GiBNfQt09BrUQMK_OSXdWuKXqdvw7sYOWtI3CGulY-vbpW43_xgCJs0yax0wEsPA_WZm06TcV3hO_c": context c
anceled
2021/04/19 19:31:56 INFO  : TEST/test_DB.accdb: vfs cache: upload canceled
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: cancelled upload
2021/04/19 19:31:56 INFO  : TEST/test_DB.accdb: vfs cache: removed cache file as stale (remote is different)
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: removed metadata from cache as stale (remote is different)
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: truncate to size=214302720
2021/04/19 19:31:56 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.accdb"
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc001956280): >openPending: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: ChunkedReader.RangeSeek from -1 to 0 length -1
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: ChunkedReader.openRange at 0 length 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728

I believe the behavior doesn't depend on file type, only size matters, because if I monitor the log and reopen the file once the upload is finished everything is ok.
Any ideas how to configure rclone in order to avoid such issue?

What is your rclone version (output from `rclone version`)

~$ sudo rclone --version

rclone v1.55.0

os/type: linux
os/arch: amd64
go/version: go1.16.2
go/linking: static
go/tags: cmount

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Ubuntu 16.04.6 LTS (GNU/Linux 4.4.0-62-generic x86_64)
$ uname -a
Linux server 4.4.0-62-generic #83-Ubuntu SMP Wed Jan 18 14:10:15 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

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

Google Drive

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

~$cat /etc/systemd/system/rclone.service

# /etc/systemd/system/rclone.service
[Unit]
Description=Drive
AssertPathIsDirectory=/storage/google


[Service]
Type=simple
ExecStart=/usr/bin/rclone mount \
        --config=/***/.rclone.conf \
        --allow-other \
        --buffer-size 32M \
        --dir-cache-time 24h \
        --log-level DEBUG \
        --log-file /var/log/rclone_google.log \
                --poll-interval 30s \
                --umask 002 \
                --vfs-cache-mode full \
                --uid 65534 \
                --gid 65534 \
                --drive-chunk-size 256M \
        --dir-cache-time=60m \
        remote-drive:backup /storage/google
ExecStop=/bin/fusermount -u /storage/google
Restart=always
RestartSec=10

[Install]
WantedBy=default.target

The rclone config contents with secrets removed.

sudo cat ./.rclone.conf

[remote-drive]
type = drive
client_id = ******
client_secret = *****
scope = drive
token = {"access_token":"y****","token_type":"Bearer","refresh_token":"****","expiry":"2021-04-19T19:49:09.6715854+03:00"}

A log from the command with the `-vv` flag

2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.accdb (rw)}: >Write: written=2, err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.accdb (rw)}: Flush: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb(0xc000f54640): RWFileHandle.Flush
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.accdb (rw)}: >Flush: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.accdb (rw)}: Release: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: Attr: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb(0xc000f54640): RWFileHandle.Release
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb(0xc000f54640): close: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: Setattr: a=Setattr [ID=0x64c14 Node=0x30b3 Uid=65534 Gid=65534 Pid=17372] atime=2021-04-19 19:31:50.537 +0300 MSK mtime=2021-04-19 19:31:50.543320731 +0300 MSK handle=INVALID-0x0
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: vfs cache: setting modification time to 2021-04-19 19:31:50.539988924 +0300 MSK m=+72671.027585055
2021/04/19 19:31:50 INFO  : TEST/test_DB.accdb: vfs cache: queuing for upload in 5s
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: vfs cache: fingerprint now "214302720,2021-04-19 16:31:20.337 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25"
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: vfs cache: setting modification time to 2021-04-19 19:31:50.543320731 +0300 MSK
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: >Setattr: err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: Attr: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/test_DB.accdb(0xc000f54640): >close: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.accdb (rw)}: >Release: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: Flush: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc00216bd00): RWFileHandle.Flush
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: >Flush: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: Release: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc00216bd00): RWFileHandle.Release
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc00216bd00): close: 
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: Flush: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc00216bd00): >close: err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc001863ac0): RWFileHandle.Flush
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: >Release: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: >Flush: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: Release: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc001863ac0): RWFileHandle.Release
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc001863ac0): close: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: Setattr: a=Setattr [ID=0x64c19 Node=0x10c3 Uid=65534 Gid=65534 Pid=17372] atime=2021-04-19 19:31:49.193 +0300 MSK mtime=2021-04-19 19:31:50.545531019 +0300 MSK handle=INVALID-0x0
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: vfs cache: setting modification time to 2021-04-19 19:31:21.147184653 +0300 MSK m=+72641.634780825
2021/04/19 19:31:50 INFO  : TEST/test_DB.laccdb: vfs cache: queuing for upload in 5s
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: vfs cache: setting modification time to 2021-04-19 19:31:50.545531019 +0300 MSK
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: >Setattr: err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: Attr: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: >Attr: a=valid=1s ino=0 size=64 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb(0xc001863ac0): >close: err=<nil>
2021/04/19 19:31:50 DEBUG : &{TEST/test_DB.laccdb (rw)}: >Release: err=<nil>
2021/04/19 19:31:50 DEBUG : TEST/: Remove: name="test_DB.laccdb"
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: Remove: 
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: vfs cache: cancelling writeback (uploading false) 0xc004815d50 item 501
2021/04/19 19:31:50 INFO  : TEST/test_DB.laccdb: vfs cache: removed cache file as file deleted
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: vfs cache: removed metadata from cache as file deleted
2021/04/19 19:31:50 DEBUG : TEST: Added virtual directory entry vDel: "test_DB.laccdb"
2021/04/19 19:31:50 DEBUG : TEST/test_DB.laccdb: >Remove: err=<nil>
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: vfs cache: starting upload
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: Sending chunk 0 length 214302720
2021/04/19 19:31:55 DEBUG : TEST/: Lookup: name="test_DB.accdb"
2021/04/19 19:31:55 DEBUG : TEST/: >Lookup: node=TEST/test_DB.accdb, err=<nil>
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: Attr: 
2021/04/19 19:31:55 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=OpenReadOnly+0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=O_RDONLY|0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: newRWFileHandle: 
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >newRWFileHandle: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fd=TEST/test_DB.accdb (rw), err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fh=&{TEST/test_DB.accdb (rw)}, err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: Flush: 
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): RWFileHandle.Flush
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: >Flush: err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: Release: 
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): RWFileHandle.Release
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): close: 
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Applied pending mod time 2021-04-19 19:31:50.543320731 +0300 MSK OK
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc0020170c0): >close: err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: >Release: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=OpenReadWrite+0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: Open: flags=O_RDWR|0x20000
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: newRWFileHandle: 
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >newRWFileHandle: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fd=TEST/test_DB.accdb (rw), err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: >Open: fh=&{TEST/test_DB.accdb (rw)}, err=<nil>
2021/04/19 19:31:56 DEBUG : &{TEST/test_DB.accdb (rw)}: Read: len=131072, offset=0
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc001956280): _readAt: size=131072, off=0
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc001956280): openPending: 
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: checking remote fingerprint "214302720,2021-04-19 16:31:50.543 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25" against cached fingerprint "214302720,2021-04-19 16:31:20.337 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25"
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: removing cached entry as stale (remote fingerprint "214302720,2021-04-19 16:31:50.543 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25" != cached fingerprint "214302720,2021-04-19 16:31:20.337 +0000 UTC,870e2168a76ddae8c4e6edcde2316a25")
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: cancelling writeback (uploading true) 0xc00012d110 item 492
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: cancelling upload
2021/04/19 19:31:56 ERROR : TEST/test_DB.accdb: Failed to copy: Post "******googleapis***/upload/drive/v3/files/1tgyX1lmZ_vxZgax332ufMYeMtWXi2GjE?alt=json&fields=id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CexplicitlyTrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails%2CexportLinks&setModifiedDate=true&supportsAllDrives=true&uploadType=resumable&upload_id=ABg5-UxS-tEA5GiBNfQt09BrUQMK_OSXdWuKXqdvw7sYOWtI3CGulY-vbpW43_xgCJs0yax0wEsPA_WZm06TcV3hO_c": context canceled
2021/04/19 19:31:56 INFO  : TEST/test_DB.accdb: vfs cache: upload canceled
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: cancelled upload
2021/04/19 19:31:56 INFO  : TEST/test_DB.accdb: vfs cache: removed cache file as stale (remote is different)
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: removed metadata from cache as stale (remote is different)
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: vfs cache: truncate to size=214302720
2021/04/19 19:31:56 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.accdb"
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb(0xc001956280): >openPending: err=<nil>
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: ChunkedReader.RangeSeek from -1 to 0 length -1
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:56 DEBUG : TEST/test_DB.accdb: ChunkedReader.openRange at 0 length 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb(0xc001956280): >_readAt: n=131072, err=<nil>
2021/04/19 19:31:57 DEBUG : &{TEST/test_DB.accdb (rw)}: >Read: read=131072, err=<nil>
2021/04/19 19:31:57 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/: Create: name="test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: Open: flags=O_RDWR|O_CREATE|O_EXCL|0x20000
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: newRWFileHandle: 
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb(0xc001455b40): openPending: 
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: vfs cache: truncate to size=0
2021/04/19 19:31:57 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb(0xc001455b40): >openPending: err=<nil>
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: >newRWFileHandle: err=<nil>
2021/04/19 19:31:57 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.laccdb"
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: >Open: fd=TEST/test_DB.laccdb (rw), err=<nil>
2021/04/19 19:31:57 DEBUG : TEST/: >Create: node=TEST/test_DB.laccdb, handle=&{TEST/test_DB.laccdb (rw)}, err=<nil>
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: Attr: 
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: Setattr: a=Setattr [ID=0x64c47 Node=0x10c3 Uid=65534 Gid=65534 Pid=17372] atime=2021-04-19 19:31:57.289 +0300 MSK mtime=2021-04-19 19:31:57.295164929 +0300 MSK handle=INVALID-0x0
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: vfs cache: setting modification time to 2021-04-19 19:31:57.295164929 +0300 MSK
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: >Setattr: err=<nil>
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: Attr: 
2021/04/19 19:31:57 DEBUG : TEST/test_DB.laccdb: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2021/04/19 19:31:57 DEBUG : &{TEST/test_DB.accdb (rw)}: Read: len=4096, offset=63983616
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb(0xc001956280): _readAt: size=4096, off=63983616
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.RangeSeek from -1 to 63983616 length -1
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at -1 length 4096 chunkOffset 63983616 chunkSize 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.openRange at 63983616 length 134217728
2021/04/19 19:31:57 DEBUG : TEST/test_DB.accdb: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
...

I may provide a complete log file if needed

ncw · April 19, 2021, 10:13pm

This looks like a bug to me.

I haven't been able to replicate it locally, but I'm pretty sure I know what the problem is.

Can you try this to see if it fixes the problem please?

v1.56.0-beta.5411.21c1f28b6.fix-vfs-dirty-remove on branch fix-vfs-dirty-remove (uploaded in 15-30 mins)

ncw · April 20, 2021, 9:49am

Sorry that didn't build (it didn't pass the tests).

Try this version which I've run through the VFS torture test - it should be good this time!

v1.56.0-beta.5417.6537ef5a5.fix-vfs-dirty-remove on branch fix-vfs-dirty-remove (uploaded in 15-30 mins)

Kirill · April 20, 2021, 3:18pm

Hi Nick! Thank you for the fast response and fix.
I've installed v1.56.0-beta.5417 and cannot reproduce the issue now, so it seems fixed

Here is log extract:

A file is closed and being uploaded:

2021/04/20 18:14:25 DEBUG : &{TEST/test_DB.accdb (rw)}: Flush:
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb(0xc00107fd00): RWFileHandle.Flush
2021/04/20 18:14:25 DEBUG : &{TEST/test_DB.accdb (rw)}: >Flush: err=<nil>
2021/04/20 18:14:25 DEBUG : &{TEST/test_DB.accdb (rw)}: Release:
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb(0xc00107fd00): RWFileHandle.Release
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb(0xc00107fd00): close:
2021/04/20 18:14:25 DEBUG : TEST/: Lookup: name="test_DB.accdb"
2021/04/20 18:14:25 DEBUG : TEST/: >Lookup: node=TEST/test_DB.accdb, err=<nil>
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb: Attr:
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb: vfs cache: setting modification time to 2021-04-20 18:14:14.920019429 +0300 MSK m=+12455.296117965
2021/04/20 18:14:25 INFO  : TEST/test_DB.accdb: vfs cache: queuing for upload in 5s
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb(0xc00107fd00): >close: err=<nil>
2021/04/20 18:14:25 DEBUG : &{TEST/test_DB.accdb (rw)}: >Release: err=<nil>
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb: Setattr: a=Setattr [ID=0x14ca7 Node=0xcf Uid=65534 Gid=65534 Pid=3341] atime=2021-04-20 18:14:14.92 +0300 MSK mtime=2021-04-20 18:14:25.592767829 +0300 MSK handle=INVALID-0x0
2021/04/20 18:14:25 DEBUG : TEST/test_DB.accdb: vfs cache: setting modification time to 2021-04-20 18:14:25.592767829 +0300 MSK
2021/04/20 18:14:26 DEBUG : TEST/test_DB.accdb: Applied pending mod time 2021-04-20 18:14:25.592767829 +0300 MSK OK
2021/04/20 18:14:26 DEBUG : TEST/test_DB.accdb: >Setattr: err=<nil>
2021/04/20 18:14:26 DEBUG : TEST/test_DB.accdb: Attr:
2021/04/20 18:14:26 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/20 18:14:27 DEBUG : TEST/: Lookup: name="test_DB.accdb"
2021/04/20 18:14:27 DEBUG : TEST/: >Lookup: node=TEST/test_DB.accdb, err=<nil>
2021/04/20 18:14:27 DEBUG : TEST/test_DB.accdb: Attr:
2021/04/20 18:14:27 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/20 18:14:30 DEBUG : TEST/test_DB.accdb: vfs cache: starting upload
2021/04/20 18:14:30 DEBUG : TEST/test_DB.accdb: Sending chunk 0 length 214302720
....

the file is reopened (the upload is still in progress):

2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.accdb"
2021/04/20 18:14:36 DEBUG : TEST/: >Lookup: node=TEST/test_DB.accdb, err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: Attr:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >Attr: a=valid=1s ino=0 size=214302720 mode=-rw-rw-r--, err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: Open: flags=OpenReadOnly+0x20000
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: Open: flags=O_RDONLY|0x20000
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: newRWFileHandle:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >newRWFileHandle: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >Open: fd=TEST/test_DB.accdb (rw), err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >Open: fh=&{TEST/test_DB.accdb (rw)}, err=<nil>
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: Flush:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc000dacb80): RWFileHandle.Flush
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: >Flush: err=<nil>
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: Release:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc000dacb80): RWFileHandle.Release
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc000dacb80): close:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc000dacb80): >close: err=<nil>
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: >Release: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: Open: flags=OpenReadWrite+0x20000
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: Open: flags=O_RDWR|0x20000
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: newRWFileHandle:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >newRWFileHandle: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >Open: fd=TEST/test_DB.accdb (rw), err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: >Open: fh=&{TEST/test_DB.accdb (rw)}, err=<nil>
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: Read: len=131072, offset=0
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc0034182c0): _readAt: size=131072, off=0
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc0034182c0): openPending:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: vfs cache: checking remote fingerprint "214302720,2021-04-20 15:14:25.592 +0000 UTC,c25fe667188cd7ccd75707fc1350c92c" against cached fingerprint "214302720,2021-04-20 12:32:33.42 +0000 UTC,c25fe667188cd7ccd75707fc1350c92c"
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: vfs cache: remote object has changed but local object modified - keeping it (remote fingerprint "214302720,2021-04-20 15:14:25.592 +0000 UTC,c25fe667188cd7ccd75707fc1350c92c" != cached fingerprint "214302720,2021-04-20 12:32:33.42 +0000 UTC,c25fe667188cd7ccd75707fc1350c92c")
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb: vfs cache: truncate to size=214302720
2021/04/20 18:14:36 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.accdb"
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc0034182c0): >openPending: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc0034182c0): >_readAt: n=131072, err=<nil>
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: >Read: read=131072, err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/: Lookup: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/: Create: name="test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: Open: flags=O_RDWR|O_CREATE|O_EXCL|0x20000
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: newRWFileHandle:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb(0xc0099f54c0): openPending:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: vfs cache: truncate to size=0
2021/04/20 18:14:36 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb(0xc0099f54c0): >openPending: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: >newRWFileHandle: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST: Added virtual directory entry vAddFile: "test_DB.laccdb"
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: >Open: fd=TEST/test_DB.laccdb (rw), err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/: >Create: node=TEST/test_DB.laccdb, handle=&{TEST/test_DB.laccdb (rw)}, err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: Attr:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: Setattr: a=Setattr [ID=0x14f2d Node=0xaa5 Uid=65534 Gid=65534 Pid=3341] atime=2021-04-20 18:14:36.79 +0300 MSK mtime=2021-04-20 18:14:36.793323278 +0300 MSK handle=INVALID-0x0
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: vfs cache: setting modification time to 2021-04-20 18:14:36.793323278 +0300 MSK
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: >Setattr: err=<nil>
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: Attr:
2021/04/20 18:14:36 DEBUG : TEST/test_DB.laccdb: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2021/04/20 18:14:36 DEBUG : &{TEST/test_DB.accdb (rw)}: Read: len=4096, offset=63983616
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc0034182c0): _readAt: size=4096, off=63983616
2021/04/20 18:14:36 DEBUG : TEST/test_DB.accdb(0xc0034182c0): >_readAt: n=4096, err=<nil>

Data is not lost and it is great!

Cheers,
Kirill

ncw · April 20, 2021, 3:44pm

Thanks for testing. I'll put this patch in 1.55.1 which should be out soon.

system · June 20, 2021, 11:45am

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