Rclone with Minio (S3) - missing files, incorrect uploads

Suspected Bug
1

Hello everyone,

I’m having an issue with Rclone on Windows (below test is from the newest beta). It’s going to be used for backing up MS SQL databases, so some DBs are couple of MB, while the biggest one has almost 650GB - so it has to work with all the files.
It mounts S3 endpoint (Minio on CentOS7) with below command:

.\rclone.exe mount Minio:BUCKET_NAME Z: --allow-other --allow-root --dir-cache-time 0 --poll-interval 0 --vfs-cache-mode writes --write-back-cache --no-check-certificate --log-level INFO --progress

First, I copied 1GB file from local to remote - it took about 4mins for Rclone to transfer the file completely (so that it’s visible on Minio server within bucket).
Then I copied 2GB file - it took about 7mins.
5GB --> still ongoing - at the time of creating this thread - for more than 1h

Windows shows progress bar each time I copy from local to remote, but it finishes after few seconds, while the files are still not visible on the remote server, so above values are when files are already physically on remote server.

2 more things I noticed:

  1. Rclone already removed mentioned 5GB file from cache (after an hour), while it’s still not on the remote server
  2. Rclone produces below info each minute, but why files are still in cache folder even though it says it cleaned it?

2019/04/18 14:30:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 0)
2019/04/18 14:31:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:32:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:33:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:33:48 INFO : File1G: Copied (new)
2019/04/18 14:34:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:35:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:36:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:37:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:38:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:39:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:40:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:41:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:42:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:43:18 INFO : Cleaned the cache: objects 2 (was 2), total size 1G (was 1G)
2019/04/18 14:44:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 1G)
2019/04/18 14:45:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:46:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:47:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:48:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:49:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:50:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:51:06 INFO : File2G: Copied (new)
2019/04/18 14:51:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:52:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:53:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:54:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:55:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:56:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:57:18 INFO : Cleaned the cache: objects 3 (was 3), total size 3G (was 3G)
2019/04/18 14:58:18 INFO : Cleaned the cache: objects 4 (was 3), total size 8G (was 3G)
2019/04/18 14:59:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:00:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:01:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:02:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:03:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:04:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:05:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:06:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:07:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:08:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:09:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:10:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:11:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:12:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:13:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:14:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:15:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:16:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:17:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:18:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:19:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:20:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:21:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:22:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:23:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:24:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:25:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:26:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:27:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:28:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:29:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:30:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:31:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:32:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:33:18 INFO : Cleaned the cache: objects 4 (was 4), total size 8G (was 8G)
2019/04/18 15:34:18 INFO : File1G: Removed from cache
2019/04/18 15:34:18 INFO : Cleaned the cache: objects 3 (was 4), total size 8G (was 8G)
2019/04/18 15:35:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 8G)
2019/04/18 15:36:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:37:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:38:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:39:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:40:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:41:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:42:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:43:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:44:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:45:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:46:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:47:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:48:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:49:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:50:18 INFO : Cleaned the cache: objects 3 (was 3), total size 7G (was 7G)
2019/04/18 15:51:18 INFO : File2G: Removed from cache
2019/04/18 15:51:18 INFO : Cleaned the cache: objects 2 (was 3), total size 7G (was 7G)
2019/04/18 15:52:18 INFO : Cleaned the cache: objects 2 (was 2), total size 5G (was 7G)
2019/04/18 15:53:18 INFO : Cleaned the cache: objects 2 (was 2), total size 5G (was 5G)
2019/04/18 15:54:18 INFO : Cleaned the cache: objects 2 (was 2), total size 5G (was 5G)
2019/04/18 15:55:18 INFO : Cleaned the cache: objects 2 (was 2), total size 5G (was 5G)
2019/04/18 15:56:18 INFO : Cleaned the cache: objects 2 (was 2), total size 5G (was 5G)
2019/04/18 15:57:18 INFO : Cleaned the cache: objects 2 (was 2), total size 5G (was 5G)
2019/04/18 15:58:18 INFO : File5G: Removed from cache
2019/04/18 15:58:18 INFO : Cleaned the cache: objects 0 (was 2), total size 5G (was 5G)

Is it possible to not use cache at all? The file is already on the disk, Rclone just copies it to cache directory, so I’m not sure what’s the point…
I will appreciate any help since I’m struggling with it for a long time now trying to figure it out.

2

Why are you using “-vfs-cache-mode writes” if you don’t want to cache things to disk first? Just remove that from your mount if you don’t need it.

You also have some odd settings with the poll interval and dir cache as both 0s. Why did you set them as that?

3

Without “–vfs-cache-mode writes”, I receive below error:

2019/04/18 17:02:33 ERROR : File1G: WriteFileHandle: Truncate: Can’t change size without --vfs-cache-mode >= writes
2019/04/18 17:02:36 ERROR : File1G: WriteFileHandle: ReadAt: Can’t read and write to file without --vfs-cache-mode >= minimal

I set “–poll-interval 0”, because I was receiving below info in log and based on documentation, setting it to “0”, should disable it - though it looks like it doesn’t, since I still receive this info.

2019/04/18 17:01:44 INFO : S3 bucket BUCKET_NAME: poll-interval is not supported by this remote

When it comes to “–dir-cache-time 0” - I was thinking setting it to “0” will disable cache, which is not the case.

4

Yeah, it checks the backend to see if it supports polling and disables polling if not supported. There is nothing needed to set for that as it’s just an informational message.

So it sounds like based on how you are writing, you need the the cache writes to be on.

How are you copying the files to the mount? It depends on how the ‘what’ is copying the file and how it is writing it. A ‘cp’ command works fine without it.

For dir-cache time, “why” would you want to disable it? That reduces API calls and speeds things up. If the remote doesn’t support polling, like yours, you may want to reduce it to something small if you are uploading things outside of the mount as that would take that amount of time to show up.

Hereis an example copy with cp for a 1GB file with no cache.

[felix@gemini GD]$ cp /data/1G.out .

[felix@gemini GD]$ rclone ls gcrypt:1G.out
1073741792 1G.out
5

Copying with “cp” command didn’t change anything.
Does anyone have any ideas what might be wrong?

6

Unfortunately, different OS’s act differently. I’m not sure on Windows how to do that.

You can always use rclone copy and copy up to the remote that way as well rather than copying directly to the mount.

7

The thing is, this is going to be used for backing up MS SQL databases. When I mount the remote, I can point to it in SSMS (SQL Server Management Studio), so backups are done directly on the remote.

8

That’s probably how the backups are written than if I doubt you can change that.

It’s not doing a complete write of the file, but opening it , writing , reading and repeating that process.

My copy command is a just a write, which is why the cache-mode isn’t needed.

9

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