Rclone mount S3 reading data hangs for several minutes

Good day

I'm running an application on AWS over several Windows 2016 servers with the support of rclone and winfsp

I'm using start rclone mount media:mediastorage/ C:\MediaStorage --vfs-cache-mode full --allow-other to mount my S3 bucket

One server uploads the media files via a web application, using regular file copy

When the other tries to read it, it hangs for several minutes before it is finally able to read

The rclone mount is performed on system startup, well before the said file would have been written to S3

I found out that if i were to stop rclone and restart it, I am able to access the files instantly. This however, is not a viable option as other operations may be going on at the same time so i can't just unmount and re-mount arbitrarily

Is there something i'm doing wrong?

Thanks

This means that is must download the whole file before it's accessible.

You can read up here:

https://rclone.org/commands/rclone_mount/#file-caching

I'm guessing that isn't what you want.

Hi, and thanks for your reply

The file isn't very large. Only about 2MB, so its not a problem if it has to download the entire file. I'm trying to copy the entire file to a local directory anyway

Can you replicate the issue and have the mount with -vv and share the debug log? We can see what it is doing.

So, this is part of the log:

2020/02/22 16:06:49 DEBUG : /UnprocessedStreams/305/1582382963.461: >Opendir: errc=0, fh=0x3
2020/02/22 16:06:49 DEBUG : /UnprocessedStreams/305/1582382963.461: Releasedir: fh=0x3
2020/02/22 16:06:49 DEBUG : /UnprocessedStreams/305/1582382963.461: >Releasedir: errc=0
2020/02/22 16:07:20 INFO : Cleaned the cache: objects 5 (was 5), total size 1.434M (was 1.434M)
2020/02/22 16:08:20 INFO : Cleaned the cache: objects 5 (was 5), total size 1.434M (was 1.434M)
2020/02/22 16:09:20 INFO : Cleaned the cache: objects 5 (was 5), total size 1.434M (was 1.434M)
2020/02/22 16:10:20 INFO : Cleaned the cache: objects 5 (was 5), total size 1.434M (was 1.434M)
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=32768
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Getattr: errc=0
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=1474560, fh=0x0
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=29119
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Getattr: errc=0
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Getattr: errc=0
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Open: flags=0x0
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/02/22 16:10:41 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327: Open: flags=O_RDONLY
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=61440, fh=0x0
2020/02/22 16:10:41 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327: >Open: fd=UnprocessedStreams/305/1582382963.461/1582382974.327 (rw), err=
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >OpenFile: fd=UnprocessedStreams/305/1582382963.461/1582382974.327 (rw), err=
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Open: errc=0, fh=0x3
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=32768
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Getattr: fh=0x3
2020/02/22 16:10:41 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Getattr: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Getattr: fh=0x3
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Getattr: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=0, fh=0x3
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00055e040): Opened existing cached copy with flags=O_RDONLY
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=262144
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=262144, fh=0x3
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=262144
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=524288, fh=0x3
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=262144
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=786432, fh=0x3
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=262144
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=1048576, fh=0x3
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=262144
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Read: ofst=1310720, fh=0x3
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Read: n=192959
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Flush: fh=0x0
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00012a0c0): RWFileHandle.Flush ignoring flush on unwritten handle
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Flush: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Release: fh=0x0
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00012a0c0): RWFileHandle.Release closing
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00012a0c0): close:
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Flush: fh=0x3
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00055e040): RWFileHandle.Flush ignoring flush on unwritten handle
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Flush: errc=0
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00012a0c0): >close: err=
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Release: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: Release: fh=0x3
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00055e040): RWFileHandle.Release closing
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00055e040): close:
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382974.327(0xc00055e040): >close: err=
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382974.327: >Release: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: >Getattr: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: >Getattr: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: Open: flags=0x0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382985.412: Open: flags=O_RDONLY
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382985.412: >Open: fd=UnprocessedStreams/305/1582382963.461/1582382985.412 (rw), err=
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: >OpenFile: fd=UnprocessedStreams/305/1582382963.461/1582382985.412 (rw), err=
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: >Open: errc=0, fh=0x0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: Getattr: fh=0x0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: >Getattr: errc=0
2020/02/22 16:10:42 DEBUG : /UnprocessedStreams/305/1582382963.461/1582382985.412: Read: ofst=0, fh=0x0
2020/02/22 16:10:42 DEBUG : UnprocessedStreams/305/1582382963.461/1582382985.412: Need to transfer - File not found at Destination

basically, it stays at that last line for a really long time
But what is stranger, is that even after it goes past that, it still takes more than 10 minutes before the read can go through

After that, i got:

2020/02/22 16:18:42 INFO : Cleaned the cache: objects 6 (was 6), total size 2.913M (was 2.913M)
2020/02/22 16:19:20 INFO : Cleaned the cache: objects 6 (was 6), total size 2.913M (was 2.913M)
2020/02/22 16:20:20 INFO : Cleaned the cache: objects 6 (was 6), total size 2.913M (was 2.913M)
2020/02/22 16:21:20 INFO : Cleaned the cache: objects 6 (was 6), total size 2.913M (was 2.913M)

At this point, the file read has still not gone through

Hmm, strange.

Can you use rclone copy to copy the file OK or does it have the same hang?

Could there be an antivirus interfering somehow?

Hi ncw

No antivirus on the servers

And windows defender scanning is disabled.

What is strange is if i stop rclone and re-mount, i get instant access

Unfortunately, as a result of the deadline, i didn't have time to do too much testing with rclone copy

i went ahead and removed --vfs-cache-mode and modified all my applications to ensure that i don't need to seek while writing

After doing that, everything works fine

Thanks for all your help ncw and Animosity022

Ah! That was probably the cause then. You should find that --vfs-cache-mode writes works OK too.