Errors in logfile -- Windows 11 & WinFsp

CSchmidt · February 10, 2022, 8:45pm

Dear Cryptomator team,

first of all I want to thank you guys for this excellent software! I consider myself an experienced user, and I used Boxcryptor Classic for many years and did the switch to Cryptomator a couple of days ago. I have Windows 11 (fresh install with newest patches) and the following remarks/questions:

Cryptomator “out of the box” (access via Webdav) was, unfortunately, a terribly bad experience. Copying files to the Webdav drive made the Webdav drive nonresponsive after a couple of (small, in the order of a couple dozen MiB) files. I nearly gave up on using Cryptomator.
I then installed WinFsp and now use the vault with FUSE fs. Works like a charm now! However, my log file is filled with hundreds of entries of the following kind:

*21:33:09.335 [Thread-39979] ERROR o.c.frontend.fuse.ReadOnlyAdapter - release /Textdokument (neu).txt failed.*
*java.nio.file.NoSuchFileException: C:\Users\rich\sciebo\VAULT\d\LF\LSW6MJ3ECSHHR2M7SDB26MUPB5HU5W\9JuwmjssEv5I1y-xskd1RFPyaFDQuoaWenRAI1H8VjRbpTqEY4g=.c9r*
*	at java.base/sun.nio.fs.WindowsException.translateToIOException(Unknown Source)*
*	at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)*
*	at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)*
*	at java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.setFileTimes(Unknown Source)*
*	at java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.setTimes(Unknown Source)*
*	at org.cryptomator.cryptofs@2.3.1/org.cryptomator.cryptofs.ch.CleartextFileChannel.persistLastModified(CleartextFileChannel.java:238)*
*	at org.cryptomator.cryptofs@2.3.1/org.cryptomator.cryptofs.ch.CleartextFileChannel.implCloseChannel(CleartextFileChannel.java:306)*
*	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(Unknown Source)*
*	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.OpenFile.close(OpenFile.java:103)*
*	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.OpenFileFactory.close(OpenFileFactory.java:78)*
*	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.ReadOnlyFileHandler.release(ReadOnlyFileHandler.java:81)*
*	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.ReadOnlyAdapter.release(ReadOnlyAdapter.java:247)*
*	at ru.serce.jnrfuse.AbstractFuseFS.lambda$init$7(AbstractFuseFS.java:150)*
*	at jnr.ffi.provider.jffi.NativeClosureProxy$$impl$$14.invoke(Unknown Source)*

Is this “normal” or pointing towards a problem? It seems like with every file I touch in the vault, a “release” fails. Also, Spyder IDE doesn’t want to save any .py file to my vault. I’ll maybe create another post for this unrelated problem.

Kind regards

overheadhunter · February 11, 2022, 5:38am

Hi and welcome!

this is indeed strange, we need to investigate this. What happens here: When about to release a file handle, the last modified date is updated under certain conditions. In this specific case, Windows complains that the to-be-updated file does not exist yet, which is unexpected since we did already write to it.

Is your sciebo directory a “normal” (i.e. locally synced) folder on a NTFS drive?

CSchmidt · February 11, 2022, 11:28pm

Hey, thanks for your quick response!

Yes, that \sciebo directory is a standard directory within the NTFS filesystem. “sciebo” is basically an owncloud-type client that watches the directory and syncs files with the cloud, just as, e.g., dropbox.

I enabled the Cryptomator diagnosis Protocol, created a new text file, saved it, then deleted it. This simple action lead to ~7k lines in the logfile. The content appears to be quite repetetive, and the “release failed” seems to appear as a result of deleting the file. I hope that the attached log file excerpt contains relevant parts:

(edit: pasted stuff without setting font to italic because that seems counter-productive here)

> creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.357 [Thread-303077] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.357 [Thread-303077] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.357 [Thread-303078] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.357 [Thread-303078] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
> 00:23:43.357 [Thread-303078] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2022-02-11T23:21:50.6717255Z, lastAccessTime: 2022-02-11T23:23:42.6800988Z, creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.357 [Thread-303078] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.357 [Thread-303078] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.359 [Thread-303079] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.360 [Thread-303079] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
> 00:23:43.360 [Thread-303079] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2022-02-11T23:21:50.6717255Z, lastAccessTime: 2022-02-11T23:23:42.6800988Z, creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.360 [Thread-303079] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.360 [Thread-303079] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.360 [Thread-303080] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.360 [Thread-303080] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
> 00:23:43.360 [Thread-303080] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2022-02-11T23:21:50.6717255Z, lastAccessTime: 2022-02-11T23:23:42.6800988Z, creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.360 [Thread-303080] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.360 [Thread-303080] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.360 [Thread-303081] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.360 [Thread-303081] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.360 [Thread-303081] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.360 [Thread-303081] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr /Textdokument (neu).txt (lastModifiedTime: 2022-02-11T23:21:53.8942396Z, lastAccessTime: 2022-02-11T23:23:42.6930639Z, creationTime: 2022-02-11T23:21:50.6717255Z, isRegularFile: true, isDirectory: false, isSymbolicLink: false, isOther: false, size: 4, fileKey: null)
> 00:23:43.360 [Thread-303081] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.360 [Thread-303081] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.360 [Thread-303081] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.360 [Thread-303082] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.361 [Thread-303082] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303082] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303082] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr /Textdokument (neu).txt (lastModifiedTime: 2022-02-11T23:21:53.8942396Z, lastAccessTime: 2022-02-11T23:23:42.6930639Z, creationTime: 2022-02-11T23:21:50.6717255Z, isRegularFile: true, isDirectory: false, isSymbolicLink: false, isOther: false, size: 4, fileKey: null)
> 00:23:43.361 [Thread-303082] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303082] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303082] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.361 [Thread-303083] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.361 [Thread-303083] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303083] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303083] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr /Textdokument (neu).txt (lastModifiedTime: 2022-02-11T23:21:53.8942396Z, lastAccessTime: 2022-02-11T23:23:42.6930639Z, creationTime: 2022-02-11T23:21:50.6717255Z, isRegularFile: true, isDirectory: false, isSymbolicLink: false, isOther: false, size: 4, fileKey: null)
> 00:23:43.361 [Thread-303083] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303083] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303083] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.361 [Thread-303084] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.361 [Thread-303084] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303084] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.361 [Thread-303084] TRACE o.c.frontend.fuse.ReadOnlyAdapter - open /Textdokument (neu).txt (0)
> 00:23:43.361 [Thread-303084] TRACE o.c.cryptofs.fh.FileHeaderHolder - Reading file header from C:\Users\rich\sciebo\VAULT\d\LF\LSW6MJ3ECSHHR2M7SDB26MUPB5HU5W\9JuwmjssEv5I1y-xskd1RFPyaFDQuoaWenRAI1H8VjRbpTqEY4g=.c9r
> 00:23:43.361 [Thread-303084] TRACE o.c.cryptofs.fh.OpenCryptoFile - First channel for this openFile. Initializing file size...
> 00:23:43.362 [Thread-303084] TRACE o.c.frontend.fuse.OpenFileFactory - Opening 1432 OpenFile{path=/Textdokument (neu).txt, channel=org.cryptomator.cryptofs.ch.CleartextFileChannel@101b711d}
> 00:23:43.362 [Thread-303084] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.362 [Thread-303084] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.362 [Thread-303084] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.362 [Thread-303085] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.362 [Thread-303085] TRACE o.c.f.fuse.locks.PathWLockImpl - Acquired write path lock for '[, Textdokument (neu).txt]'
> 00:23:43.362 [Thread-303085] TRACE o.c.f.fuse.locks.DataWLockImpl - Acquired write data lock for '[, Textdokument (neu).txt]'
> 00:23:43.362 [Thread-303085] TRACE o.c.frontend.fuse.ReadWriteAdapter - unlink /Textdokument (neu).txt
> 00:23:43.362 [Thread-303085] TRACE o.c.f.fuse.locks.DataWLockImpl - Released write data lock for '[, Textdokument (neu).txt]'
> 00:23:43.362 [Thread-303085] TRACE o.c.f.fuse.locks.PathWLockImpl - Released write path lock for '[, Textdokument (neu).txt]'
> 00:23:43.362 [Thread-303085] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.363 [Thread-303086] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.363 [Thread-303086] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.363 [Thread-303086] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.363 [Thread-303086] TRACE o.c.frontend.fuse.ReadOnlyAdapter - release /Textdokument (neu).txt (1432)
> 00:23:43.363 [Thread-303086] TRACE o.c.frontend.fuse.OpenFileFactory - Releasing 1432 OpenFile{path=/Textdokument (neu).txt, channel=org.cryptomator.cryptofs.ch.CleartextFileChannel@101b711d}
> 00:23:43.363 [Thread-303086] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[, Textdokument (neu).txt]'
> 00:23:43.363 [Thread-303086] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[, Textdokument (neu).txt]'
> 00:23:43.363 [Thread-303087] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.363 [Thread-303086] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.363 [Thread-303087] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
> 00:23:43.363 [Thread-303087] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2022-02-11T23:23:43.3622863Z, lastAccessTime: 2022-02-11T23:23:43.3622863Z, creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.363 [Thread-303087] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.363 [Thread-303087] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.363 [Thread-303086] ERROR o.c.frontend.fuse.ReadOnlyAdapter - release /Textdokument (neu).txt failed.
> java.nio.file.NoSuchFileException: C:\Users\rich\sciebo\VAULT\d\LF\LSW6MJ3ECSHHR2M7SDB26MUPB5HU5W\9JuwmjssEv5I1y-xskd1RFPyaFDQuoaWenRAI1H8VjRbpTqEY4g=.c9r
> 	at java.base/sun.nio.fs.WindowsException.translateToIOException(Unknown Source)
> 	at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)
> 	at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)
> 	at java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.setFileTimes(Unknown Source)
> 	at java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.setTimes(Unknown Source)
> 	at org.cryptomator.cryptofs@2.3.1/org.cryptomator.cryptofs.ch.CleartextFileChannel.persistLastModified(CleartextFileChannel.java:238)
> 	at org.cryptomator.cryptofs@2.3.1/org.cryptomator.cryptofs.ch.CleartextFileChannel.implCloseChannel(CleartextFileChannel.java:306)
> 	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(Unknown Source)
> 	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.OpenFile.close(OpenFile.java:103)
> 	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.OpenFileFactory.close(OpenFileFactory.java:78)
> 	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.ReadOnlyFileHandler.release(ReadOnlyFileHandler.java:81)
> 	at org.cryptomator.frontend.fuse@1.3.3/org.cryptomator.frontend.fuse.ReadOnlyAdapter.release(ReadOnlyAdapter.java:247)
> 	at ru.serce.jnrfuse.AbstractFuseFS.lambda$init$7(AbstractFuseFS.java:150)
> 	at jnr.ffi.provider.jffi.NativeClosureProxy$$impl$$14.invoke(Unknown Source)
> 00:23:43.363 [Thread-303088] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.363 [Thread-303088] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
> 00:23:43.363 [Thread-303088] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2022-02-11T23:23:43.3622863Z, lastAccessTime: 2022-02-11T23:23:43.3622863Z, creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.363 [Thread-303088] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.363 [Thread-303088] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.365 [Thread-303089] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.365 [Thread-303089] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'
> 00:23:43.365 [Thread-303089] TRACE o.c.frontend.fuse.ReadOnlyAdapter - getattr / (lastModifiedTime: 2022-02-11T23:23:43.3622863Z, lastAccessTime: 2022-02-11T23:23:43.3622863Z, creationTime: 2022-02-05T22:18:13.7328071Z, isRegularFile: false, isDirectory: true, isSymbolicLink: false, isOther: false, size: 20480, fileKey: null)
> 00:23:43.365 [Thread-303089] TRACE o.c.f.fuse.locks.DataRLockImpl - Released read data lock for '[]'
> 00:23:43.365 [Thread-303089] TRACE o.c.f.fuse.locks.PathRLockImpl - Released read path lock for '[]'
> 00:23:43.366 [Thread-303090] TRACE o.c.f.fuse.locks.PathRLockImpl - Acquired read path lock for '[]'
> 00:23:43.366 [Thread-303090] TRACE o.c.f.fuse.locks.DataRLockImpl - Acquired read data lock for '[]'

overheadhunter · February 13, 2022, 7:12am

Thanks, this helps. release after unlink should obviously not attempt to change any date. This is a bug, but nothing you need to worry about.