Long delay in mount point showing up on Windows

What is the problem you are having with rclone?

Long delay in mount point showing up on Windows when upload folder is not empty.

What is your rclone version (output from rclone version)

rclone v1.54.0
- os/arch: windows/amd64
- go version: go1.15.7

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Windows 10 64 bit

Which cloud storage system are you using? (eg Google Drive)

Google Drive

The command you were trying to run (eg rclone copy /tmp remote:tmp)

C:\bin\rclone.exe mount gdrive: Z: --attr-timeout 1s --buffer-size 100M --cache-db-path "C:\tmp\rclone\cache\gdrive\root\db" --cache-dir "C:\tmp\rclone\cache\gdrive\root" --cache-tmp-upload-path "C:\tmp\rclone\cache\gdrive\root\upload" --dir-cache-time 1000h --drive-chunk-size 64M --drive-skip-gdocs --exclude-if-present ".ignore" --log-level INFO --poll-interval 1m --progress --rc --rc-addr "192.168.1.108:8081" --rc-no-auth --rc-web-gui --stats 0 --timeout 1h --tpslimit 10 --transfers 1 --use-mmap --user-agent "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36" --vfs-cache-max-age 1500h --vfs-cache-max-size 250G --vfs-cache-mode full --vfs-cache-poll-interval 5m --vfs-read-chunk-size 2M --vfs-read-chunk-size-limit 2048M --volname "Google Drive"

The rclone config contents with secrets removed.

[gdrive]
type = drive
client_id = ***REDACTED***
client_secret = ***REDACTED***
scope = drive
root_folder_id = ***REDACTED***
use_trash = false
chunk_size = 32M
acknowledge_abuse = true
server_side_across_configs = true
token = {"access_token":"***REDACTED***","token_type":"Bearer","refresh_token":"***REDACTED***","expiry":"2021-03-06T08:58:43.7177923Z"}

A log from the command with the -vv flag

>C:\bin\rclone.exe mount gdrive: Z: --attr-timeout 1s --buffer-size 100M --cache-db-path "C:\tmp\rclone\cache\gdrive\root\db" --cache-dir "C:\tmp\rclone\cache\gdrive\root" --cache-tmp-upload-path "C:\tmp\rclone\cache\gdrive\root\upload" --dir-cache-time 1000h --drive-chunk-size 64M --drive-skip-gdocs --exclude-if-present ".ignore" --log-level DEBUG --poll-interval 1m --progress --rc --rc-addr "192.168.1.108:8081" --rc-no-auth --rc-web-gui --stats 0 --timeout 1h --tpslimit 10 --transfers 1 --use-mmap --user-agent "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36" --vfs-cache-max-age 1500h --vfs-cache-max-size 250G --vfs-cache-mode full --vfs-cache-poll-interval 5m --vfs-read-chunk-size 2M --vfs-read-chunk-size-limit 2048M --volname "Google Drive"
2021/03/06 08:29:09 DEBUG : rclone: Version "v1.54.0" starting with parameters ["C:\\bin\\rclone.exe" "mount" "gdrive:" "Z:" "--attr-timeout" "1s" "--buffer-size" "100M" "--cache-db-path" "C:\\tmp\\rclone\\cache\\gdrive\\root\\db" "--cache-dir" "C:\\tmp\\rclone\\cache\\gdrive\\root" "--cache-tmp-upload-path" "C:\\tmp\\rclone\\cache\\gdrive\\root\\upload" "--dir-cache-time" "1000h" "--drive-chunk-size" "64M" "--drive-skip-gdocs" "--exclude" "*.!qB" "--exclude" "**.!qB" "--exclude-if-present" ".ignore" "--log-level" "DEBUG" "--poll-interval" "1m" "--progress" "--rc" "--rc-addr" "192.168.1.108:8081" "--rc-no-auth" "--rc-web-gui" "--stats" "0" "--timeout" "1h" "--tpslimit" "10" "--transfers" "1" "--use-mmap" "--user-agent" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36" "--vfs-cache-max-age" "1500h" "--vfs-cache-max-size" "250G" "--vfs-cache-mode" "full" "--vfs-cache-poll-interval" "5m" "--vfs-read-chunk-size" "2M" "--vfs-read-chunk-size-limit" "2048M" "--volname" "Google Drive"]
2021/03/06 08:29:10 DEBUG : Current tag: v2.0.4, Release tag: v2.0.4
2021/03/06 08:29:10 NOTICE: Web GUI exists. Update skipped.
2021/03/06 08:29:10 INFO  : Cannot run Web GUI without authentication, using default auth
2021/03/06 08:29:10 NOTICE: Serving Web GUI
2021/03/06 08:29:10 INFO  : Using --user ***REDACTED*** --pass XXXX as authenticated user
2021/03/06 08:29:10 NOTICE: Serving remote control on http://192.168.1.108:8081/
2021/03/06 08:29:10 DEBUG : login_token "***REDACTED***"
2021/03/06 08:29:10 DEBUG : Creating backend with remote "gdrive:"
2021/03/06 08:29:10 DEBUG : Using config file from "C:\\Users\\***REDACTED***\\.config\\rclone\\rclone.conf"
2021/03/06 08:29:10 INFO  : Starting bandwidth limiter at 250kBytes/s
2021/03/06 08:29:10 INFO  : Starting transaction limiter: max 10 transactions/s with burst 1
2021/03/06 08:29:10 DEBUG : vfs cache: root is "\\\\?\\C:\\tmp\\rclone\\cache\\gdrive\\root\\vfs\\gdrive"
2021/03/06 08:29:10 DEBUG : vfs cache: metadata root is "\\\\?\\C:\\tmp\\rclone\\cache\\gdrive\\root\\vfs\\gdrive"
2021/03/06 08:29:10 DEBUG : Creating backend with remote "\\\\?\\C:\\tmp\\rclone\\cache\\gdrive\\root\\vfs\\gdrive"
2021/03/06 08:29:10 DEBUG : fs cache: renaming cache item "\\\\?\\C:\\tmp\\rclone\\cache\\gdrive\\root\\vfs\\gdrive" to be canonical "//?/C:/tmp/rclone/cache/gdrive/root/vfs/gdrive"
2021/03/06 08:29:10 DEBUG : fs cache: switching user supplied name "\\\\?\\C:\\tmp\\rclone\\cache\\gdrive\\root\\vfs\\gdrive" for canonical name "//?/C:/tmp/rclone/cache/gdrive/root/vfs/gdrive"
2021/03/06 08:29:13 DEBUG : rc: "core/stats": with parameters map[]
2021/03/06 08:29:13 DEBUG : rc: "core/version": with parameters map[]
2021/03/06 08:29:13 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:3.9201969 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/06 08:29:13 DEBUG : rc: "core/stats": with parameters map[]
2021/03/06 08:29:13 DEBUG : rc: "core/version": reply map[arch:amd64 decomposed:[1 54 0] goVersion:go1.15.7 isBeta:false isGit:false os:windows version:v1.54.0]: <nil>
2021/03/06 08:29:13 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletedDirs:0 deletes:0 elapsedTime:3.9451819 errors:0 fatalError:false renames:0 retryError:false speed:0 transferTime:0 transfers:0]: <nil>
2021/03/06 08:29:23 DEBUG : path/to/file.ext: vfs cache: truncate to size=16012804096
2021/03/06 08:29:23 DEBUG : path/to/file.ext: vfs cache: setting modification time to 2021-03-05 22:41:15.8844258 +0000 UTC
2021/03/06 08:29:23 INFO  : path/to/file.ext: vfs cache: queuing for upload in 5s
2021/03/06 08:29:28 DEBUG : path/to/file.ext: vfs cache: starting upload
2021/03/06 08:29:29 DEBUG : path/to/file.ext: Sending chunk 0 length 67108864
2021/03/06 08:30:10 DEBUG : Google drive root '': Checking for changes on remote
2021/03/06 08:30:11 DEBUG : : invalidating directory cache

You have a lot of options in your command, do you know what they do and that they are needed? I know --fast-list does nothing on mount, so you can remove that at least. Also you have both --rc-no-auth and --rc-user/--rc-passwd, seems to me you don't need both, although I have no experience with rc myself.

I would try with as simple command as possible first, and then extend from that, perhaps you can find a combination of options that triggers your issue.

What is a long delay? 30 seconds? 5 minutes? 20 minutes?

Based on the log, it looks like you are good to go in about 13 seconds if I'm not mistaken.

It's hours, I'm not sure where you got the 13 seconds from but the Z: mount point hasn't shown up for the last hour or so.

I've restarted the mount recently though as I removed the --fast-list and --rc-user --rc-pass.

That is when it starts.

Looks to be viable around here.

You've only included a snippet of the log though if it's problematic after that so it's a guessing game.

Yes because its a very very long log file, and there is lots of duplication, the only difference is a different file is entered into the upload queue.

That would cause a delay but without seeing the log, we just guess.

If you want to include a usable log here, that is how we can help identify the issue.

Ok well where would you like the log to stop? As the log file keeps filling up until I presume all the files in the upload dir have entered the queue, at which point I guess the mount point would appear? This takes hours as it seems to be uploading files as they enter the queue, this slows it down significantly so I believe it's waiting for the upload queue to be empty before it shows the mount point. If that is the case the mount point isn't likely to appear for approx a week at a guess, and the log file will continue to grow for that amount of time also.

If you share the full log, that's helps the most.

I understand that it helps the most, but the log I posted above that file is 15gb in size, and the gui says it's going to take 17 hours to upload, which is fine but obviously I have an issue with the mount point not showing up, and would ideally like the mount point to show up before the 17 hours is up, there is several other files after this one with varying sizes, so it's going to be a very long wait to get a full log to you and my issue resolved it appears.

You can zip it up before you upload it somewhere.

You can make a Google Drive link to it.

You can make a One Drive link to it.

You can share it any myriad of ways that is easier / best for you.

If you want an answer and help, a full log file is needed.

If it doesn't matter to you why, you can just mark it solved and that's that.

No you misunderstand, the providing the log is not the problem.

The problem is the amount of physical time that will have passed to get you a full log.

As I said the first file in the upload queue will take 17 hours to upload, and the files after this I don't know how long they will take to upload.

So if I can't get a full log to you for over a week? that means I just have to have a non working mount for that amount of time, does that make sense what I am trying to explain?

If you have a large set of files in your upload queue, the mount doesn't become active until the queue is cleaned out so I'd assume you stopped the mount before things cleared out.

By providing the full log in the first post, we would have arrived at that answer after the first post. Since you only gave a brief snippet in the first post, we spent some time trying to get a picture of what's going on.

So if you provide the current full log, we can show you what's going on based on the log.

@ncw Is there a reason for that? No not stopped as such, more of Windows decided it wanted to do an update and the machine rebooted whilst I was sleeping.

That's all that was in the log at the point of making the post I couldn't give you more at the time, but I did state there was a large upload queue.

Confused, I have looked at the log and can see that files are uploading, there isn't much else going on. Confused as to why there is a delay in the mount becoming active just because there is an upload queue.

Still no log file?

Getting into a catch-22 here. If you share the log, I can show you.

hello,
some of these flags do nothing, based on your config
--cache-db-path
-cache-tmp-upload-path

to simply testing, remove all the flags and test with a simple command such as rclone.exe mount gdrive: Z:
if it works well, then add more flags, test and repeat until the delay happens, and then you will know which flag is causing the delay.
if the command still has the delay, then continue to diagnose the problem with that simple command.

The issue isn't any flags, it's the upload queue that has to be processed.

That is shown in the logs..

Not sure your internet stats, but the transfers being at 1 only allows 1 transfer at a time so that will slow things down.

You got files queued up to upload as you'll see a bunch of these in your log:

2021/03/06 12:18:27 DEBUG : ***REDACTED***: vfs cache: delaying writeback as --transfers exceeded

You can do a count since the file names are all redacted.

It's trying to empty the queue before it returns the mount.

What's the size of your backlog?

I did that as I didn't want the uploads to take up all the transactions and leave too few for reading, so I thought I would just do 1 at a time and as I am in rush for the files to be uploaded.

How would I check that ?

There is 67 files in the upload folder, there is more in the vfs folder but I believe thats the cache.