search

cryptomator / fuse-cloud-access-adapter

FUSE access to cloud-access-java
GNU Affero General Public License v3.0
2 stars 1 forks source link

ClosedChannelException thrown when working with LibreOffice #3

Closed infeo closed 4 years ago

infeo commented 4 years ago

Library: WinFSP OS: Windows 10 Pro 2004

Using the localFSProvider of the cloud-access-java library to mirror a local directory, a ClosedChannelException is thrown if one opens an existing office document with LibreOffice 6.3.6.2. There seems no other apparent error.

Sequence of actions:

  1. Create in the dir to mirror an office document (e.g. a spread sheet)
  2. Open the document with LibreOffice
  3. Make a change in document and save it.

Frequency: Intermittent.

Log: This is not the complete log of filesystem calls. Apart from the normal logging the release() method of the CloudAccessFS and the close() method of CachedFile are logged additonally.

14:21:09.455 [main] INFO org.cryptomator.fusecloudaccess.MirrorTest - Mounting FUSE file system at XXX...
The service java has been started.
14:21:11.477 [main] INFO org.cryptomator.fusecloudaccess.MirrorTest - Type anything and hit enter to stop.
14:21:18.095 [Thread-160] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.095 [Thread-160] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.095 [Thread-160] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.095 [Thread-164] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.095 [Thread-164] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.095 [Thread-164] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.095 [Thread-168] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.095 [Thread-168] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.095 [Thread-168] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.111 [Thread-195] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.126 [Thread-195] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.126 [Thread-195] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.126 [Thread-199] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.126 [Thread-199] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.126 [Thread-199] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.126 [Thread-208] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.126 [Thread-208] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.126 [Thread-208] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.126 [Thread-217] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.126 [Thread-217] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.126 [Thread-217] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.126 [Thread-221] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.126 [Thread-221] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.126 [Thread-221] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.126 [Thread-225] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.126 [Thread-225] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.126 [Thread-225] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.142 [Thread-281] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.142 [Thread-281] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.142 [Thread-281] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.158 [Thread-285] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.158 [Thread-285] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.158 [Thread-285] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.173 [Thread-294] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.173 [Thread-294] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.173 [Thread-294] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /yolo.ods.
14:21:18.873 [Thread-412] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /.~lock.yolo.ods#.
14:21:18.873 [Thread-412] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /.~lock.yolo.ods#.
14:21:18.873 [Thread-412] DEBUG org.cryptomator.fusecloudaccess.CachedFile - uploading /.~lock.yolo.ods#...
14:21:18.873 [Thread-412] DEBUG org.cryptomator.fusecloudaccess.CachedFile - uploaded /.~lock.yolo.ods#
14:21:18.873 [Thread-412] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /.~lock.yolo.ods#.
14:21:18.873 [Thread-421] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /.~lock.yolo.ods#.
14:21:18.873 [Thread-421] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /.~lock.yolo.ods#.
14:21:18.873 [Thread-421] DEBUG org.cryptomator.fusecloudaccess.CachedFile - uploading /.~lock.yolo.ods#...
14:21:18.873 [Thread-421] ERROR org.cryptomator.fusecloudaccess.CloudAccessFS - release() failed
java.util.concurrent.CompletionException: java.nio.channels.ClosedChannelException
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
    at java.base/java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:670)
    at java.base/java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:658)
    at java.base/java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:2094)
    at java.base/java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:143)
    at org.cryptomator.fusecloudaccess.CloudAccessFS.release(CloudAccessFS.java:207)
    at ru.serce.jnrfuse.AbstractFuseFS.lambda$init$7(AbstractFuseFS.java:144)
    at jnr.ffi.provider.jffi.NativeClosureProxy$$impl$$11.invoke(Unknown Source)
Caused by: java.nio.channels.ClosedChannelException
    at java.base/sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:150)
    at java.base/sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:349)
    at org.cryptomator.fusecloudaccess.CachedFile.releaseFileHandle(CachedFile.java:103)
    at org.cryptomator.fusecloudaccess.CachedFileHandle.release(CachedFileHandle.java:89)
    at org.cryptomator.fusecloudaccess.CachedFileFactory.close(CachedFileFactory.java:92)
    ... 3 more
14:21:18.873 [Thread-426] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /.~lock.yolo.ods#.
14:21:18.873 [Thread-426] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /.~lock.yolo.ods#.
14:21:18.873 [Thread-426] DEBUG org.cryptomator.fusecloudaccess.CachedFile - Close() is called for the cached file of /.~lock.yolo.ods#.
14:21:18.873 [Thread-445] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.873 [Thread-445] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.873 [Thread-449] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.873 [Thread-449] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:18.888 [Thread-454] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:18.888 [Thread-454] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.220 [Thread-469] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.220 [Thread-469] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.220 [Thread-473] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.220 [Thread-473] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.220 [Thread-482] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.220 [Thread-482] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.220 [Thread-491] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.220 [Thread-491] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.220 [Thread-495] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.220 [Thread-495] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.220 [Thread-499] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.220 [Thread-499] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.622 [Thread-560] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.622 [Thread-560] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.622 [Thread-564] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.622 [Thread-564] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.622 [Thread-573] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.622 [Thread-573] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.622 [Thread-582] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.622 [Thread-582] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.637 [Thread-586] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.637 [Thread-586] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
14:21:19.637 [Thread-590] DEBUG org.cryptomator.fusecloudaccess.CloudAccessFS - release is called for /yolo.ods.
14:21:19.637 [Thread-590] DEBUG org.cryptomator.fusecloudaccess.CachedFile - releaseFileHandle() is called for cached file of /yolo.ods.
overheadhunter commented 4 years ago

Problem is that the upload task must not be triggered more than once, which needs some refactoring of this method:

https://github.com/cryptomator/fuse-cloud-access-adapter/blob/818c01eace6fd1ce4898863829c8f0d5eec6bffd/src/main/java/org/cryptomator/fusecloudaccess/CachedFile.java#L91-L113

infeo commented 4 years ago

The cause for this bug is, that a cached file is removed only at the very end of the close() method from the CachedFileFactory.

Assume you have opend a CachedFile file in the CachedFileFactory and only one CachedFileHandle handle refering to file, hence it is present in the files map. Now CachedFileFactory::close with the handle id is called, then there is a short moment in time, where file does not have any handles,therefore passes the check handles.isEmpty() and will close the file, but the cached file is still present in the factory, such that a new CachedFIleHandle refering to file can be returned.

overheadhunter commented 4 years ago

Did some small changes, however we need a larger refactoring here, since it can still happen that a thread opens a file which is currently being uploaded and therefore re-downloads an outdated old version.

overheadhunter commented 4 years ago

@infeo Is this solved?

infeo commented 4 years ago

yes.