Mount disconnects - only during write

sommewt · April 27, 2020, 4:35pm

What is the problem you are having with rclone?

History:
I've used this particular rclone mount for around 9 months as a dedicated Plex server with no issues. I recently migrated all of my applications from another seedbox (also using rclone) to the same server. I have no issues when Plex is scanning library files, playing and transcoding multiple streams, etc. I've bounced around a few seedbox providers (bytesized, whatbox, ultraseedbox) and used various rclone mounts over the years, so I'm somewhat familiar with what works for my setup. I've had Plex/Sonarr/Radarr/NZBget/Ombi/Tautulli all running over rclone mounts in the past on these linux based seedboxes with no issues, so I don't think it's a problem with my Google drive. I've kept a record of the different .conf files for comparison over the years and over the last few days I've tried a few different options to troubleshoot. I'm not hitting any API limit warnings as far as I know.

Behavior
This is most noticeable during a stream, but I suspect it also happens when I'm not looking. When Sonarr or Radarr grabs files from the NZBget download directory (on local drive) renames them, and relocates/writes to the rclone mount drive (X:) the mount temporarily disconnects and pauses any read operations ( the plex stream hangs). Once the write operation is complete the drive usually reconnects and the plex stream resumes. If it's a large amount of data being written by Sonarr/Radarr and the plex stream completely times out, I can restart the rclone service and the drive will reappear. This is what it looks like in Windows Explorer:

functioning drive appearance:
(only allowed one image, but it's a normal mapped drive that shows drive capaicity and volume name)

broken drive appearance:
broken

I'm suspecting this is more of a Windows/networking problem just based on the lack of info in the rclone logs, but hoping someone else might have run into the same issue. There is no helpful information to be found in the Windows Event Viewer.

What is your rclone version (output from `rclone version`)

rclone v1.51.0

os/arch: windows/amd64
go version: go1.13.7

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

Windows Server 2019 Standard 64 bit

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

Google Drive (around 70TB)

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

Currently I'm using nssm to run rclone as a service (with winfsp) with this command:

mount gdrive: X: 
--allow-other 
--dir-cache-time 72h 
--drive-chunk-size 64M 
--log-level INFO 
--log-file "C:\rclone\info.log" 
--vfs-read-chunk-size 32M 
--vfs-read-chunk-size-limit off 
--vfs-cache-mode writes
--config "C:\Users\admin\.config\rclone\rclone.conf"

A log from the command with the `-vv` flag (eg output from `rclone -vv copy /tmp remote:tmp`)

I'm creating an INFO log in my default config, but it does not contain any errors. I switched to DEBUG for troubleshooting, no errors, but logs pasted below.

This is the debug log upon service start:

2020/04/27 07:25:39 DEBUG : rclone: Version "v1.51.0" starting with parameters ["C:\\rclone\\rclone.exe" "mount" "--allow-other" "--dir-cache-time" "72h" "--drive-chunk-size" "64M" "--log-level" "DEBUG" "--log-file" "C:\\rclone\\debug2.log" "--vfs-read-chunk-size" "32M" "--vfs-read-chunk-size-limit" "off" "gdrive:" "X:" "--config" "C:\\Users\\admin\\.config\\rclone\\rclone.conf" "--vfs-cache-mode" "writes"]
2020/04/27 07:25:39 DEBUG : Using config file from "C:\\Users\\admin\\.config\\rclone\\rclone.conf"
2020/04/27 07:25:39 DEBUG : Google drive root '': Mounting on "X:"
2020/04/27 07:25:41 DEBUG : vfs cache root is "C:\\Windows\\system32\\config\\systemprofile\\AppData\\Local\\rclone\\vfs\\gdrive"
2020/04/27 07:25:41 DEBUG : Adding path "vfs/forget" to remote control registry
2020/04/27 07:25:41 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/04/27 07:25:41 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/04/27 07:25:41 DEBUG : Google drive root '': Mounting with options: ["-o" "fsname=gdrive:" "-o" "subtype=rclone" "-o" "max_readahead=131072" "-o" "attr_timeout=1" "-o" "atomic_o_trunc" "-o" "uid=-1" "-o" "gid=-1" "--FileSystemName=rclone" "-o" "volname=gdrive" "-o" "allow_other"]
2020/04/27 07:25:41 DEBUG : Google drive root '': Init: 
2020/04/27 07:25:41 DEBUG : Google drive root '': >Init: 
2020/04/27 07:25:41 DEBUG : /: Statfs: 
2020/04/27 07:25:41 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:256221602839 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Readlink: 
2020/04/27 07:25:41 DEBUG : /: >Readlink: linkPath="", errc=-40
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Opendir: 
2020/04/27 07:25:41 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/04/27 07:25:41 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/04/27 07:25:41 DEBUG : /: >Opendir: errc=0, fh=0x0
2020/04/27 07:25:41 DEBUG : /: Releasedir: fh=0x0
2020/04/27 07:25:41 DEBUG : /: >Releasedir: errc=0
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Opendir: 
2020/04/27 07:25:41 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/04/27 07:25:41 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/04/27 07:25:41 DEBUG : /: >Opendir: errc=0, fh=0x0
2020/04/27 07:25:41 DEBUG : /: Releasedir: fh=0x0
2020/04/27 07:25:41 DEBUG : /: >Releasedir: errc=0
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:41 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:41 DEBUG : /: Opendir: 
2020/04/27 07:25:41 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/04/27 07:25:41 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/04/27 07:25:41 DEBUG : /: >Opendir: errc=0, fh=0x0
2020/04/27 07:25:41 DEBUG : /: Releasedir: fh=0x0
2020/04/27 07:25:41 DEBUG : /: >Releasedir: errc=0
2020/04/27 07:25:44 DEBUG : /autorun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:46 DEBUG : /autorun.inf: >Getattr: errc=-2
2020/04/27 07:25:46 DEBUG : /autorun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:46 DEBUG : /autorun.inf: >Getattr: errc=-2
2020/04/27 07:25:46 DEBUG : /autorun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:46 DEBUG : /autorun.inf: >Getattr: errc=-2
2020/04/27 07:25:46 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:46 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:46 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:46 DEBUG : /: >Getattr: errc=0
2020/04/27 07:25:46 DEBUG : /: Opendir: 
2020/04/27 07:25:46 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/04/27 07:25:46 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/04/27 07:25:46 DEBUG : /: >Opendir: errc=0, fh=0x0
2020/04/27 07:25:46 DEBUG : /: Releasedir: fh=0x0
2020/04/27 07:25:46 DEBUG : /: >Releasedir: errc=0
2020/04/27 07:25:46 DEBUG : /AutoRun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:25:46 DEBUG : /AutoRun.inf: >Getattr: errc=-2
2020/04/27 07:25:53 DEBUG : /Media/Movies/HyperNormalisation (2016): Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:26:01 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:26:01 DEBUG : /: >Getattr: errc=0
2020/04/27 07:26:01 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:26:01 DEBUG : /: >Getattr: errc=0
2020/04/27 07:26:01 DEBUG : /: Opendir: 
2020/04/27 07:26:01 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/04/27 07:26:01 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/04/27 07:26:01 DEBUG : /: >Opendir: errc=0, fh=0x0
2020/04/27 07:26:01 DEBUG : /: Releasedir: fh=0x0
2020/04/27 07:26:01 DEBUG : /: >Releasedir: errc=0
2020/04/27 07:26:01 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:26:01 DEBUG : /: >Getattr: errc=0
2020/04/27 07:26:01 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/04/27 07:26:01 DEBUG : /: >Getattr: errc=0
2020/04/27 07:26:01 DEBUG : /: Opendir: 
2020/04/27 07:26:01 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/04/27 07:26:01 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/04/27 07:26:01 DEBUG : /: >Opendir: errc=0, fh=0x0
2020/04/27 07:26:01 DEBUG : /: Statfs: 
2020/04/27 07:26:01 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:256221602839 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2020/04/27 07:26:01 DEBUG : /: Releasedir: fh=0x0
2020/04/27 07:26:01 DEBUG : /: >Releasedir: errc=0

The last successful read:

2020/04/27 07:33:22 DEBUG : /Media/Movies/movie.mkv: Read: ofst=617244461, fh=0x0
2020/04/27 07:33:22 DEBUG : /Media/Movies/movie.mkv: >Read: n=229796

The last successful write:

2020/04/27 07:36:10 DEBUG : Media/TV/show.mkv: Sending chunk 2483027968 length 67108864

This is the last non read/write line after crashing when I killed the process:

2020/04/27 07:35:41 DEBUG : Google drive root '': Checking for changes on remote
2020/04/27 07:35:41 INFO  : Cleaned the cache: objects 10 (was 10), total size 14.546G (was 14.546G)

asdffdsa · April 27, 2020, 4:41pm

hello and welcome to the fourm,

what version of winfsp are you running?
v1.6 is the latest stable

what do you mean "the mount temporarily disconnects"?

sommewt · April 27, 2020, 4:50pm

Winfsp is version 1.6.20027

I tried to show it with the image, but the mounted drive created by the rclone mount kind of disappears temporarily, but not a full disconnected drive.

asdffdsa · April 27, 2020, 4:53pm

can you be more specific?
so the x: drive disappears from windows explorer?
if you do a dir x:, what output do you get?

sommewt · April 27, 2020, 5:01pm

I think the closest technical term for it in Windows is a "phantom drive." It has a drive letter, is labeled "Local Disk" and show's no disk capacity or usage.

This is the normal state of the drive:
nomal

I just tried running a dir command while it was in this phantom state and the command took about 30 seconds, but finally displayed the directory contents. At this point the drive was displaying normally.

asdffdsa · April 27, 2020, 5:02pm

so you moved to another seedbox or everything is now running on the windows server?

sommewt · April 27, 2020, 5:05pm

I had it split before, but now everything is on this Windows server.

asdffdsa · April 27, 2020, 5:08pm

--allow-other does nothing on windows...

"Plex/Sonarr/Radarr/NZBget/Ombi/Tautulli"
are you running all of these on windows?

perhaps the vfs is causing problems.
are you sure you need it?
in my mounts, i do not use vfs at all.

sommewt · April 27, 2020, 5:49pm

I'll take the allow-other out.

I don't have Tautulli installed at the moment, but yes the rest are running. I'll try with vfs off or set to minimal to see if anything changes.

asdffdsa · April 27, 2020, 5:51pm

vfs minimal and writes is for when you open a file and edit/modify it, like with notepad.

if you are copying files from local to x:, no need for vfs at all.

i would try to simplify everything.
mount gdrive: X: no flags at all.
if your rclone.conf is in the default location, then you do not need that config flag.

then just plex, none of the other programs.
then try to copy a large file to x: and see if plex stops.

sommewt · April 27, 2020, 6:09pm

I tried both just for testing, but "minimal" made it worse, and "off" seems to have fixed the issue with the phantom drive.

Thanks for the help asdffdsa, lesson learned that rclone mount cache settings don't always translate from Linux to Windows for write operations at least. I have 4 test transcodes running while uploading using rclone at 250Mbps and the drive is stable.

asdffdsa · April 27, 2020, 6:14pm

sure, glad that i could help.

ncw · April 28, 2020, 4:58pm

I think what is happening is that when you are using --vfs-cache-mode writes when the file closes it writes the file back to the cloud storage. It keeps the directory locked at this point which means that any other accesses to the directory are blocked which could lead to the symptoms of the file system being locked up.

Using --vfs-cache-mode off means the files get written straight to cloud storage so no long pause at the end.

I'm in the process of fixing this by writing back the files asynchronously to the cloud storage (and they will restart on rclone restart). I think this will help a lot on Windows. For some reason Linux doesn't seem to be bothered by this issue.

sommewt · April 28, 2020, 6:53pm

Just to update on a new behavior I've noticed. Without the vfs enabled, I guess the rclone mount was able to use 100% of the available bandwidth and the CPU usage skyrocketed (as high as 78% just for rclone.exe). I used the bwlimit option set at 100M and it seems to have helped a little. Not a deal breaker, but just a change I observed.

system · May 1, 2020, 6:53pm

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