VFS hangs up for network error

Suspected Bug
1

What is the problem you are having with rclone?

For rclone mount:

  1. Add a file to VFS
  2. rclone finished upload it
  3. rclone get the changeNotify

and if there is any temporary network error like timeout, VFS will hang up until network back to work

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

rclone v1.65.0
- os/version: ubuntu 20.04 (64 bit)
- os/kernel: 5.4.0-169-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.21.4
- go/linking: static
- go/tags: none

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

Onedrive

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

rclone mount odrive:linode /onedrive --allow-other --transfers 4 --buffer-size 64M --cache-dir /root/onedrive_cache --vfs-cache-mode full --vfs-read-chunk-size 2M --vfs-read-chunk-size-limit 0M --vfs-cache-max-size 5G --vfs-cache-max-age 3360h --allow-non-empty --dir-cache-time 3360h --umask 000 --vfs-cache-poll-interval 3h --vfs-write-back 3s --poll-interval 5s --log-file /root/rclone.txt --log-level DEBUG

The rclone config contents with secrets removed.

[odrive]
type = onedrive
client_id = ffeeed50-ea2e-4a3c-8713-6ec66fe0c696
client_secret = ...
token = {"access_token":"...","token_type":"Bearer","refresh_token":"..."}
drive_id = b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl
drive_type = business

A log from the command with the -vv flag

2023/12/19 13:21:14 DEBUG : rclone: Version "v1.65.0" starting with parameters ["rclone" "mount" "odrive:linode" "/onedrive" "--allow-other" "--transfers" "4" "--buffer-size" "64M" "--cache-dir" "/root/onedrive_cache" "--vfs-cache-mode" "full" "--vfs-read-chunk-size" "2M" "--vfs-read-chunk-size-limit" "0M" "--vfs-cache-max-size" "5G" "--vfs-cache-max-age" "3360h" "--allow-non-empty" "--dir-cache-time" "3360h" "--umask" "000" "--vfs-cache-poll-interval" "3h" "--vfs-write-back" "3s" "--poll-interval" "5s" "--log-file" "/root/rclone.txt" "--log-level" "DEBUG"]
2023/12/19 13:21:14 DEBUG : Creating backend with remote "odrive:linode"
2023/12/19 13:21:14 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2023/12/19 13:21:14 DEBUG : odrive: Loaded invalid token from config file - ignoring
2023/12/19 13:21:14 DEBUG : odrive: Token refresh failed try 1/5: Post "https://login.microsoftonline.com/common/oauth2/v2.0/token": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:15 DEBUG : odrive: Loaded invalid token from config file - ignoring
2023/12/19 13:21:15 DEBUG : Saving config "token" in section "odrive" of the config file
2023/12/19 13:21:15 DEBUG : odrive: Saved new token in config file
2023/12/19 13:21:15 DEBUG : OneDrive root 'linode': Next delta token is: NDslMjM0OyUyMzE7MzswYzhhOWNhZS0xMzY5LTQ0Y2EtOWZkZS05MTI5ZDk3MmQ2MjU7NjM4Mzg1ODg4NzUwMDMwMDAwOzE5ODE3NDUxMjslMjM7JTIzOyUyMzA7JTIz
2023/12/19 13:21:15 DEBUG : vfs cache: root is "/root/onedrive_cache"
2023/12/19 13:21:15 DEBUG : vfs cache: data root is "/root/onedrive_cache/vfs/odrive/linode"
2023/12/19 13:21:15 DEBUG : vfs cache: metadata root is "/root/onedrive_cache/vfsMeta/odrive/linode"
2023/12/19 13:21:15 DEBUG : Creating backend with remote "/root/onedrive_cache/vfs/odrive/linode"
2023/12/19 13:21:15 DEBUG : Creating backend with remote "/root/onedrive_cache/vfsMeta/odrive/linode"
2023/12/19 13:21:15 DEBUG : OneDrive root 'linode': Mounting on "/onedrive"
2023/12/19 13:21:15 DEBUG : vfs cache RemoveNotInUse (maxAge=12096000000000000, emptyOnly=false): item ca/cf/test.txt not removed, freed 0 bytes
2023/12/19 13:21:15 DEBUG : vfs cache RemoveNotInUse (maxAge=12096000000000000, emptyOnly=false): item cb/cf/test.txt not removed, freed 0 bytes
2023/12/19 13:21:15 DEBUG : vfs cache RemoveNotInUse (maxAge=12096000000000000, emptyOnly=false): item test/test.txt not removed, freed 0 bytes
2023/12/19 13:21:15 DEBUG : vfs cache RemoveNotInUse (maxAge=12096000000000000, emptyOnly=false): item test.txt not removed, freed 0 bytes
2023/12/19 13:21:15 INFO  : vfs cache: cleaned: objects 4 (was 4) in use 0, to upload 0, uploading 0, total size 31 (was 31)
2023/12/19 13:21:15 DEBUG : : Root: 
2023/12/19 13:21:15 DEBUG : : >Root: node=/, err=<nil>
2023/12/19 13:21:16 DEBUG : /: Lookup: name="test.txt"
2023/12/19 13:21:16 DEBUG : /: >Lookup: node=test.txt, err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: Attr: 
2023/12/19 13:21:16 DEBUG : test.txt: >Attr: a=valid=1s ino=0 size=15 mode=-rw-rw-rw-, err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: Open: flags=OpenWriteOnly
2023/12/19 13:21:16 DEBUG : test.txt: Open: flags=O_WRONLY
2023/12/19 13:21:16 DEBUG : test.txt: newRWFileHandle: 
2023/12/19 13:21:16 DEBUG : test.txt: >newRWFileHandle: err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: >Open: fd=test.txt (rw), err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: >Open: fh=&{test.txt (rw)}, err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: Setattr: a=Setattr [ID=0xa Node=0x2 Uid=0 Gid=0 Pid=601379] size=0 handle=INVALID-0x0 lockowner
2023/12/19 13:21:16 DEBUG : test.txt: Truncating 1 file handles
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): openPending: 
2023/12/19 13:21:16 DEBUG : test.txt: vfs cache: checking remote fingerprint "15,2023-12-19 13:11:11 +0000 UTC,5440431ae6008234cc0104610f0115ca30073a28" against cached fingerprint "15,2023-12-19 13:11:11 +0000 UTC,5440431ae6008234cc0104610f0115ca30073a28"
2023/12/19 13:21:16 DEBUG : test.txt: vfs cache: truncate to size=15 (not needed as size correct)
2023/12/19 13:21:16 DEBUG : : Added virtual directory entry vAddFile: "test.txt"
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): >openPending: err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: vfs cache: truncate to size=0
2023/12/19 13:21:16 DEBUG : test.txt: >Setattr: err=<nil>
2023/12/19 13:21:16 DEBUG : test.txt: Attr: 
2023/12/19 13:21:16 DEBUG : test.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-rw-, err=<nil>
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: Flush: 
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): RWFileHandle.Flush
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: Write: len=15, offset=0
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): _writeAt: size=15, off=0
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): >_writeAt: n=15, err=<nil>
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: >Write: written=15, err=<nil>
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: Flush: 
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): RWFileHandle.Flush
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: Release: 
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): RWFileHandle.Release
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): close: 
2023/12/19 13:21:16 DEBUG : vfs cache: looking for range={Pos:0 Size:15} in [{Pos:0 Size:15}] - present true
2023/12/19 13:21:16 DEBUG : test.txt: vfs cache: setting modification time to 2023-12-19 13:21:16.324752483 +0000 UTC m=+2.056246773
2023/12/19 13:21:16 INFO  : test.txt: vfs cache: queuing for upload in 3s
2023/12/19 13:21:16 DEBUG : test.txt(0xc000ce59c0): >close: err=<nil>
2023/12/19 13:21:16 DEBUG : &{test.txt (rw)}: >Release: err=<nil>
2023/12/19 13:21:19 DEBUG : test.txt: vfs cache: starting upload
2023/12/19 13:21:19 DEBUG : test.txt: Starting multipart upload
2023/12/19 13:21:19 DEBUG : test.txt: Uploading segment 0/15 size 15
2023/12/19 13:21:20 DEBUG : test.txt: quickxor = 5440431ae6008234cc0104610f0115ca30073a28 OK
2023/12/19 13:21:20 INFO  : test.txt: Copied (replaced existing)
2023/12/19 13:21:20 DEBUG : test.txt: vfs cache: fingerprint now "15,2023-12-19 13:21:16 +0000 UTC,5440431ae6008234cc0104610f0115ca30073a28"
2023/12/19 13:21:20 DEBUG : test.txt: vfs cache: writeback object to VFS layer
2023/12/19 13:21:20 DEBUG : : Added virtual directory entry vAddFile: "test.txt"
2023/12/19 13:21:20 INFO  : test.txt: vfs cache: upload succeeded try #1
2023/12/19 13:21:20 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:20 DEBUG : : changeNotify: relativePath="test.txt", type=1
2023/12/19 13:21:20 DEBUG : : invalidating directory cache
2023/12/19 13:21:20 DEBUG : : >changeNotify: 
2023/12/19 13:21:25 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:30 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:30 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=NDslMjM0OyUyMzE7MzswYzhhOWNhZS0xMzY5LTQ0Y2EtOWZkZS05MTI5ZDk3MmQ2MjU7NjM4Mzg1ODg4ODM1MTMwMDAwOzE5ODE3NDUyNTslMjM7JTIzOyUyMzA7JTIz": unexpected EOF
2023/12/19 13:21:35 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:35 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": unexpected EOF
2023/12/19 13:21:40 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:40 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:45 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:45 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:48 DEBUG : /: Attr: 
2023/12/19 13:21:48 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 13:21:48 DEBUG : /: ReadDirAll: 
2023/12/19 13:21:48 DEBUG : pacer: low level retry 1/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2023/12/19 13:21:48 DEBUG : pacer: low level retry 2/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2023/12/19 13:21:48 DEBUG : pacer: low level retry 3/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2023/12/19 13:21:48 DEBUG : pacer: low level retry 4/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2023/12/19 13:21:48 DEBUG : pacer: low level retry 5/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2023/12/19 13:21:48 DEBUG : pacer: low level retry 6/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2023/12/19 13:21:48 DEBUG : pacer: low level retry 7/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:48 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2023/12/19 13:21:49 DEBUG : pacer: low level retry 8/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:49 DEBUG : pacer: Rate limited, increasing sleep to 2s
2023/12/19 13:21:50 DEBUG : pacer: low level retry 9/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:50 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:50 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:52 DEBUG : pacer: low level retry 10/10 (error Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused)
2023/12/19 13:21:52 DEBUG : : Dir.ReadDirAll error: couldn't list files: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:52 ERROR : IO error: couldn't list files: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:52 DEBUG : /: >ReadDirAll: item=-1, err=couldn't list files: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXLKBYIEMXSYCRG3KVHDFJVXVTLY/children?$top=1000": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:21:55 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:21:55 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:22:00 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:22:00 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:22:05 DEBUG : OneDrive root 'linode': Checking for changes on remote
2023/12/19 13:22:05 INFO  : OneDrive root 'linode': Change notify listener failure: Get "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/root/delta?token=": proxyconnect tcp: dial tcp [::1]:8080: connect: connection refused
2023/12/19 13:22:09 INFO  : Signal received: interrupt
2023/12/19 13:22:09 DEBUG : vfs cache: cleaner exiting
2023/12/19 13:22:09 ERROR : /onedrive: Unmounted rclone mount
2023/12/19 13:22:09 INFO  : Exiting...

Here is my test script:
run.sh:

#!/bin/sh
# run.sh
screen -d -m -S pproxy ./startpproxy.sh
screen -d -m -S rclone ./startRclone.sh

startRclone.sh:

#!/bin/sh
# startRclone.sh
export http_proxy=http://localhost:8080
export https_proxy=http://localhost:8080
rclone mount odrive:linode /onedrive --allow-other --transfers 4 --buffer-size 64M --cache-dir /root/onedrive_cache --vfs-cache-mode full --vfs-read-chunk-size 2M --vfs-read-chunk-size-limit 0M --vfs-cache-max-size 5G --vfs-cache-max-age 3360h --allow-non-empty --dir-cache-time 3360h --umask 000 --vfs-cache-poll-interval 3h --vfs-write-back 3s --poll-interval 5s --log-file /root/rclone.txt --log-level DEBUG

startpproxy.sh:

#!/bin/sh
# startpproxy.sh
pproxy &
PID_1=$!
sleep 2
echo "This is a Test" > /onedrive/test.txt
sleep 10
kill $PID_1
pproxy -b rules &
PID=$!
sleep 10
kill $PID

rules:

(?:.+\.)?graph\.microsoft.*\.com

I use python-proxy to simulate the network timeout, when you see rclone finished file upload and get the changeNotify, type ls /onedrive:
ls: reading directory '/onedrive': Input/output error
if the request timeout for like 2 mins, the VFS will hang up for even more long time.

2

That's execpted as you have a network based file system and you lose the network, it times out and hangs.

What are you expecting to happen?

3

I see, I originally thought that when you adding a file to cache, it will update your dir cache as well, but it seems to be separate operation, maybe we can add a option to recursively load all dir cache at startup, and when add a file or a folder, update it's dir cache as well?

4

I still can't quite understand what you are trying to figure out.

If you have a network mount and the network is gone, things go bad and you get time outs.

It's like when you hit a browser page and you time out, nothing really 'works' until you fix the network and depending on how bad things / how long things were out, you most likely want to reboot things.

I can't connect on the cache part and updating and what not if there isn't a network.

Polling remotes pick up changes via their polling internval and any changes made outside the mount are reflected on the mount based on the poll internval which is default 1 minute.

There already is an option to load the mount structure on startup as well.

      --vfs-refresh                            Refreshes the directory cache recursively on start
5

When a network request timeout, rclone will block all the following files request, maybe not recursively read lock the dir until network request finished? Here is the log:
rclone_log (github.com)

partitial log:

2023/12/19 02:27:15 DEBUG : : Statfs: 
2023/12/19 02:27:15 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:27:19 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: vfs cache: starting upload
2023/12/19 02:27:19 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: Starting multipart upload
2023/12/19 02:27:19 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: Uploading segment 0/186684 size 186684
2023/12/19 02:27:20 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: quickxor = ee67891cba74c626a92efc355f22a129f1997c0d OK
2023/12/19 02:27:20 INFO  : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: Copied (new)
2023/12/19 02:27:20 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: vfs cache: fingerprint now "186684,2023-12-19 02:22:19 +0000 UTC,ee67891cba74c626a92efc355f22a129f1997c0d"
2023/12/19 02:27:20 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: vfs cache: writeback object to VFS layer
2023/12/19 02:27:20 DEBUG : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: Not setting pending mod time 2023-12-19 02:22:19.09816 +0000 UTC as it is already set
2023/12/19 02:27:20 DEBUG : cache/01/ad: Added virtual directory entry vAddFile: "01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg"
2023/12/19 02:27:20 INFO  : cache/01/ad/01ad393a661065f904759ead1bcc1b4c659c86c0-186684-1280-1713-jpg: vfs cache: upload succeeded try #1
2023/12/19 02:27:23 DEBUG : : Statfs: 
2023/12/19 02:27:23 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:27:31 DEBUG : : Statfs: 
2023/12/19 02:27:31 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:27:39 DEBUG : : Statfs: 
2023/12/19 02:27:39 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:27:46 DEBUG : pacer: low level retry 1/10 (error Patch "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXO6HO4MUQQMFBA3HNN2D47KAAR3:/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg:": read tcp XX.XXX.XX.XX:43674->XX.XX.X.X:443: i/o timeout)
2023/12/19 02:27:46 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2023/12/19 02:27:46 DEBUG : pacer: Reducing sleep to 15ms
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Applied pending mod time 2023-12-19 02:22:45.987 +0000 UTC OK
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Setattr: err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Attr: 
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Attr: a=valid=1s ino=0 size=538525 mode=-rw-rw-rw-, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/: >Lookup: node=cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Attr: 
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Attr: a=valid=1s ino=0 size=538525 mode=-rw-rw-rw-, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/: >Lookup: node=cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Attr: 
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Attr: a=valid=1s ino=0 size=538525 mode=-rw-rw-rw-, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/: Lookup: name="6a"
2023/12/19 02:27:46 DEBUG : cache/: >Lookup: node=cache/6a/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/6a/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/6a/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/: Lookup: name="a1"
2023/12/19 02:27:46 DEBUG : cache/: >Lookup: node=cache/a1/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/6a/: Lookup: name="ba"
2023/12/19 02:27:46 DEBUG : cache/: Lookup: name="13"
2023/12/19 02:27:46 DEBUG : cache/6a/: >Lookup: node=cache/6a/ba/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/: >Lookup: node=cache/13/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/13/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/13/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/6a/ba/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/6a/ba/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/a1/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/a1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/13/: Lookup: name="eb"
2023/12/19 02:27:46 DEBUG : cache/13/: >Lookup: node=cache/13/eb/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/a1/: Lookup: name="ca"

You can see that all the lookup was block just because only one network request timeout, and other upload session works normally.

6

On network time outs, it retries as you can see from the log.

I still have no idea what problem you are trying to solve or what you are asking yet so sorry as I'm not following.

7

I'm sorry for not explaining clearly. My native language was not English, so I'll try my best to explain it.

Main issue is:
First, the mutex read lock was lock recursively when get filesystem request, then rclone send a API request to Onedrive, but if this request get io timeout, until the request timeout error was raised, the mutex read lock will not unlock, cause the lookup request behind the network request was blocked.

Here rclone does nothing due to the mutex lock, but actually there are a lot of lookup request was blocked:

2023/12/19 02:23:02 DEBUG : cache/93/20/: Lookup: name="9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg"
2023/12/19 02:23:07 DEBUG : : Statfs: 
2023/12/19 02:23:07 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:23:15 DEBUG : : Statfs: 
2023/12/19 02:23:15 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>

...

2023/12/19 02:27:23 DEBUG : : Statfs: 
2023/12/19 02:27:23 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:27:31 DEBUG : : Statfs: 
2023/12/19 02:27:31 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/12/19 02:27:39 DEBUG : : Statfs: 
2023/12/19 02:27:39 DEBUG : : >Statfs: stat={Blocks:1342177280 Bfree:1331389319 Bavail:1331389319 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>

And the lookup function started to work until the timeout error was raised:

2023/12/19 02:27:46 DEBUG : pacer: low level retry 1/10 (error Patch "https://graph.microsoft.com/v1.0/drives/b!QT-vBfWDykuEFt9u5LUVNJ3gNgu-9H5JtcpAQf5duVOunIoMaRPKRJ_ekSnZctYl/items/01QPGQHXO6HO4MUQQMFBA3HNN2D47KAAR3:/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg:": read tcp XX.XXX.XX.XX:43674->XX.XX.X.X:443: i/o timeout)
2023/12/19 02:27:46 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2023/12/19 02:27:46 DEBUG : pacer: Reducing sleep to 15ms
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Applied pending mod time 2023-12-19 02:22:45.987 +0000 UTC OK
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Setattr: err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Attr: 
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Attr: a=valid=1s ino=0 size=538525 mode=-rw-rw-rw-, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/: >Lookup: node=cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Attr: 
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Attr: a=valid=1s ino=0 size=538525 mode=-rw-rw-rw-, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/: >Lookup: node=cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: Attr: 
2023/12/19 02:27:46 DEBUG : cache/93/20/9320be8481572d8afa546a6af52e53edd55babbd-538525-1280-1572-jpg: >Attr: a=valid=1s ino=0 size=538525 mode=-rw-rw-rw-, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/: Lookup: name="6a"
2023/12/19 02:27:46 DEBUG : cache/: >Lookup: node=cache/6a/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/6a/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/6a/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/: Lookup: name="a1"
2023/12/19 02:27:46 DEBUG : cache/: >Lookup: node=cache/a1/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/6a/: Lookup: name="ba"
2023/12/19 02:27:46 DEBUG : cache/: Lookup: name="13"
2023/12/19 02:27:46 DEBUG : cache/6a/: >Lookup: node=cache/6a/ba/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/: >Lookup: node=cache/13/, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/13/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/13/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/6a/ba/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/6a/ba/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/a1/: Attr: 
2023/12/19 02:27:46 DEBUG : cache/a1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxrwx, err=<nil>
2023/12/19 02:27:46 DEBUG : cache/13/: Lookup: name="eb"

So, I expected that others lookup request should not be blocked due to the rare network timeout and should work normally.

8

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