rclone vfs - cache cleanup leads to error "Device not configured (os error 6)"

[rustikus]

Thanks for the great software!

I am using rclone to access my files stored in a public cloud and gocryptfs to encrypt everything. To not download all files but have something like a smart selective sync I use rclone mount - https://rclone.org/commands/rclone_mount/

This works fine especially using VFS file caching of rclone - https://rclone.org/commands/rclone_mount/#vfs-file-caching

I use the following options to mount the directories:

rclone --vfs-cache-mode full --allow-other

gocryptfs -ko modules=iconv,from_code=UTF-8,to_code=UTF-8-MAC

Nevertheless after some time the mounted directory of gocryptfs is not accessible anymore and gives an error Device not configured (os error 6)

If I unmount the gocryptfs directory and mount it again with gocryptfs everything is working again. So the rclone mount seems to work fine.

Not sure what I am doing wrong or where to find more specific logs. The only hint I found was that some files were removed from cache automatically by rclone. Does this have an effect on gocryptfs?

Environment:

$ gocryptfs --version                    
gocryptfs v2.2.1-6-gd530fbd without_openssl; 
go-fuse v2.1.1-0.20210825171523-3ab5d95a30ae; 
2021-11-02 go1.17.2 darwin/arm64

$ rclone --version
rclone v1.57.0
- os/version: darwin 12.0.1 (64 bit)
- os/kernel: 21.1.0 (arm64)
- os/type: darwin
- os/arch: arm64
- go/version: go1.17.2
- go/linking: dynamic
- go/tags: cmount

[rustikus]

A quick update.

I suspected this to be related to the VFS cache of rclone but I am not so sure anymore. The same problem occurs with encfs so it might also be related to macFUSE (used by gocryptfs / encfs)

I tried to replicate the issue to check if it is related to rclone removing the cache files (including .gocryptfs.diriv).

# Mount OneDrive via rclone and VFS cache but limit cache to 10 seconds
rclone mount ondrive: mnt/rclone --vfs-cache-mode full --allow-other --vfs-cache-max-age 10s --debug-fuse -v

# Mount gocryptfs
gocryptfs mnt/rclone/gocryptfs mnt/dec

But until now I was not able to replicate the issue.

[rustikus]

I finally got an error in the debug logs. Hopefully this helps.

12:45:27.226758 rx 2: ACCESS n1 {u=501 g=20 }
12:45:27.226890 tx 2:     OK
12:45:27.227098 rx 4: ACCESS n1 {u=501 g=20 }
12:45:27.227204 tx 4:     OK
12:45:27.227372 rx 3: STATFS n1
12:45:27.227456 tx 3:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:45:27.227759 rx 2: ACCESS n1 {u=501 g=20 }
12:45:27.227883 tx 2:     OK
12:45:27.227984 rx 4: STATFS n1
12:45:27.228058 tx 4:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:45:27.228171 rx 3: ACCESS n1 {u=501 g=20 }
12:45:27.228274 tx 3:     OK
12:45:27.228468 rx 2: ACCESS n1 {u=501 g=20 }
12:45:27.228572 tx 2:     OK
12:45:27.228681 rx 4: STATFS n1
12:45:27.228745 tx 4:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:45:58.438111 rx 3: ACCESS n1 {u=501 g=20 }
12:46:21.878524 tx 3:     5=input/output error
12:46:42.785306 rx 2: STATFS n1
12:46:42.792090 tx 2:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:46:42.809899 rx 4: ACCESS n1 {u=501 g=20 }
12:46:42.815981 rx 3: STATFS n1
12:46:42.816146 tx 3:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:46:42.867428 rx 2: STATFS n1
12:46:42.867499 tx 2:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:47:21.888107 tx 4:     5=input/output error
12:47:21.888545 rx 3: ACCESS n1 {u=501 g=20 x}
12:47:51.894012 tx 3:     5=input/output error
12:47:51.896208 rx 2: ACCESS n1 {u=501 g=20 }
12:47:51.960647 rx 4: STATFS n1
12:47:51.960919 tx 4:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:47:51.970290 rx 3: STATFS n1
12:47:51.970397 tx 3:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:48:02.982740 rx 4: STATFS n1
12:48:02.983659 tx 4:     OK, {blocks (1073741823,1073741823)/1073741823 files 1000000000/1000000000 bs16384 nl0 frs16384}
12:48:12.002323 rx 8: FORGET n31 {Nlookup=1}
12:48:12.002585 rx 3: FORGET n37 {Nlookup=1}
12:48:12.002647 rx 4: FORGET n36 {Nlookup=1}
12:48:12.002700 rx 3: FORGET n35 {Nlookup=1}
12:48:12.002747 rx 7: FORGET n32 {Nlookup=1}
12:48:12.002780 rx 5: FORGET n34 {Nlookup=1}
12:48:12.002829 rx 4: FORGET n29 {Nlookup=1}
12:48:12.002865 rx 9: FORGET n23 {Nlookup=1}
12:48:12.002894 rx 3: FORGET n21 {Nlookup=1}
12:48:12.002920 rx 3: FORGET n28 {Nlookup=1}
12:48:12.002756 rx 6: FORGET n33 {Nlookup=1}
12:48:12.002991 rx 8: FORGET n17 {Nlookup=1}
12:48:12.003021 rx 6: FORGET n26 {Nlookup=1}
12:48:12.002799 rx 9: FORGET n16 {Nlookup=1}
12:48:12.003080 rx 16: FORGET n9 {Nlookup=1}
12:48:12.003109 rx 10: FORGET n15 {Nlookup=1}
12:48:12.003143 rx 14: FORGET n11 {Nlookup=1}
12:48:12.003172 rx 15: FORGET n10 {Nlookup=1}
12:48:12.002814 rx 9: FORGET n30 {Nlookup=1}
12:48:12.003236 rx 17: FORGET n8 {Nlookup=1}
12:48:12.003267 rx 21: FORGET n4 {Nlookup=1}
12:48:12.003300 rx 19: FORGET n6 {Nlookup=1}
12:48:12.003348 rx 23: FORGET n2 {Nlookup=1}
12:48:12.002880 rx 4: FORGET n22 {Nlookup=1}
12:48:12.002944 rx 5: FORGET n20 {Nlookup=1}
12:48:12.002962 rx 6: FORGET n19 {Nlookup=1}
12:48:12.002978 rx 7: FORGET n18 {Nlookup=1}
12:48:12.003008 rx 5: FORGET n27 {Nlookup=1}
12:48:12.003044 rx 7: FORGET n25 {Nlookup=1}
12:48:12.003058 rx 8: FORGET n24 {Nlookup=1}
12:48:12.003096 rx 12: FORGET n13 {Nlookup=1}
12:48:12.003129 rx 13: FORGET n12 {Nlookup=1}
12:48:12.003157 rx 11: FORGET n14 {Nlookup=1}
12:48:12.003194 rx 20: FORGET n5 {Nlookup=1}
12:48:12.003256 rx 22: FORGET n3 {Nlookup=1}
12:48:12.003287 rx 18: FORGET n7 {Nlookup=1}
12:48:12.003436 rx 24: FORGET n18446744073709551615 {Nlookup=1}
12:48:51.896120 rx 4: INTERRUPT n0 {ix 2}
12:49:21.904935 tx 2:     5=input/output error
12:49:21.905280 rx 3: ACCESS n1 {u=0 g=0 }
cli args: ["gocryptfs" "--fg" "--debug" "--fusedebug" "-ko" "allow_other,modules=iconv,from_code=UTF-8,to_code=UTF-8-MAC" "-config" "/Users/user/Documents/test.gocryptfs" "-fsname" "TEST" "/Users/user/mnt/rclone/test" "/Users/user/Documents/test"]
12:49:51.911044 tx 3:     5=input/output error
12:49:51.913995 rx 5: FSYNCDIR n1
12:50:25.733326 tx 5:     OK
12:50:25.735014 rx 6: ACCESS n1 {u=0 g=0 }
12:50:25.736821 tx 6:     OK
12:50:25.737432 rx 7: GETATTR n1
12:50:25.738194 tx 7:     OK, {tA=1s {M040755 SZ=0 L=1 501:20 0 0:0 A 1572164854.000000 M 1572164854.000000 C 1572164854.000000}}
12:50:25.738523 rx 8: FSYNCDIR n1
12:50:25.739031 tx 8:     OK
12:50:25.739187 rx 9: RELEASEDIR n1 {Fh 1   L0}
12:50:25.739236 tx 9:     OK
12:50:25.744178 rx 10: DESTROY n1
12:50:25.744302 tx 10:     OK
12:50:25.758728 received ENODEV (unmount request), thread exiting
CryptoCore.Wipe: Only nil'ing stdlib refs

[haifengkao]

I got the same problem just by copying files into gocryptfs's decipher folder.

[krim404]

can confirm, this issue is driving me nuts.

[magnusja]

Have this under Catalina when using rsync.

[magnusja]

Also have this with v1.8 and osfuxe 3.11.2

[magnusja]

Having the same problem with cryfs. Seems that I am not the only one: cryfs/cryfs#393

Maybe not so much related to gocryptfs but rather macFuse?

[Tyr-Wang]

sounds like macFuse's problem, try umount -f <path> as temporary workaround

[rfjakob]

In the log, i see stuff like this: 12:45:58.438111 rx 3: ACCESS n1 {u=501 g=20 } 12:46:21.878524 tx 3: 5=input/output error That's not good at all. The kernel tried to access the root dir in the mountpoint and got an i/o error. The fact that there are no error messages from gocryptfs tells me that the i/o error was thrown in rclone. What does the rclone log say when this happens?

…

On Fri, 2 Feb 2024, 17:33 Tyr-Wang, ***@***.***> wrote: sounds like macFuse's problem, try umount -f <path> as temporary workaround — Reply to this email directly, view it on GitHub <#620 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACGA733UIGD57RLGM5B2I3YRUINZAVCNFSM5IQUBDH2U5DIOJSWCZC7NNSXTN2JONZXKZKDN5WW2ZLOOQ5TCOJSGQZDENBQGY4Q> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>