Rclone Mount Access Stops Occasionally. Pulling My Hair Out

Help and Support
1

What is the problem you are having with rclone?

Hi,

I randomly have my mounts drop access. I have 3 mounts.. all with identical mount config. 1 for Movies, 1 for TV, and 1 for MTV.

I have error level at DEBUG and have run "tail -f rcm.txt" to watch the logs for errors when it happens but do not see any errors.

The services are started and running, and don't drop out, stop or have errors when the problem occurs.

I have seen once a " task Plex Media Server:20706 blocked for 120 seconds" error which led me to network issues. I then removed IPV6 , and added

sudo sysctl -w vm.dirty_ratio=10
sudo sysctl -w vm.dirty_background_ratio=5

But don't see this much, and not when the failure occurs.

Plex will run a movie without dropouts, it almost appears to happen when you stop a movie and go to access another. I have Plex player set to Secure only, which makes no difference. The error will occur on Web Plex, Nvidia Shield, Mac Desktop App and Phone, so it is a player issue i don't beleive.

I can log onto the other mounts, and list the directories with a result when one mount fails, yet with the mount that is down, I cannot list directory until it resolves itself.

The mounts usually stops for a minute or two and then returns to normal.

I cannot see huge Google API activity, nor API lockouts when this happens.

I have run out of ideas and pretty close to losing patience.. Any help would be appreciated.

Thanks

What is your rclone version (output from rclone version)

rclone v1.51.0

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

18.04

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)

[Unit]
Description=Google Movies Drive (rclone)
AssertPathIsDirectory=/mnt/movies


[Service]
KillMode=none
Type=simple
ExecStart=/usr/bin/rclone mount \
        --user-agent='Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36' \
        --config=/home/plex/.config/rclone/rclone.conf \
        --log-file=/logs/rcm.txt \
        --log-level DEBUG \
        --allow-other \
        --allow-non-empty \
        --umask 002 \
        --buffer-size 32M \
        --dir-cache-time 72h \
        --drive-chunk-size 32M \
        --vfs-read-chunk-size 64M \
        --vfs-read-chunk-size-limit off \
        --vfs-cache-mode writes plex-movies:/ /mnt/movies
ExecStop=/bin/fusermount -u /mnt/movies
Restart=on-failure
RestartSec=2

[Install]
WantedBy=default.target

The rclone config contents with secrets removed.

Paste config here

A log from the command with the -vv flag

Paste  log here
2

Have you check the memory usage when the mount "crash" ?

3

hi, no I haven't. whats the best way to check that ? and can I allocate more memory to the process ?

4

I'm a windows user, don't know a lot about checking ram usage under nix. I guess the "top" command will do ?
I talk about ram, because, with a -buffer-size too high, you can consume a lot of ram if too many files are open at the same time, and when plex is scanning, i guess it can pretty quickly get out of hands ?

It's just a supposition.

5

thanks anyway.

System Memory usage on GTOP states 22%

and in process ID they are not being flooded from what I can see.

6

Just failed again without errors.. although I can see this

Child 2098 (pager) died (code=exited, status=2/INVALIDARGUMENT)

Can anyone elaborate on what this would be ?

it appears that the system crashes when the Rclone Mount isn't accessed for some time.. say 10 minutes.

Thanks

7

You want to run the mount in debug with -vv and share the log as that will show what's going on.

I'm not sure what you mean when you say "system crashes". If you server is crashing, that's something a bit larger and not rclone.

8

Hi Animosity.

Here is a log from when it just failed.

020/05/18 20:30:15 DEBUG : Google drive root '': Checking for changes on remote
2020/05/18 20:30:16 DEBUG : : Statfs:
2020/05/18 20:30:16 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:17 DEBUG : : Statfs:
2020/05/18 20:30:17 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:17 DEBUG : /: Attr:
2020/05/18 20:30:17 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 20:30:17 DEBUG : /: Lookup: name="Agent Jade Black (2020).mp4"
2020/05/18 20:30:18 DEBUG : : Statfs:
2020/05/18 20:30:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:19 DEBUG : : Statfs:
2020/05/18 20:30:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:20 DEBUG : : Statfs:
2020/05/18 20:30:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:21 DEBUG : : Statfs:
2020/05/18 20:30:21 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:22 DEBUG : : Statfs:
2020/05/18 20:30:22 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:23 DEBUG : : Statfs:
2020/05/18 20:30:23 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:24 DEBUG : : Statfs:
2020/05/18 20:30:24 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:25 DEBUG : : Statfs:
I then get Statfs for the time until it gets online again

basically what happens is if I do not access the mount for some time, when I go to use it, it will drop off , I cannot see the mount in a directory list, and Plex will not play the item until it comes back online.

a couple of minutes later the mount comes online and the logs show the browsing of movies, and then show the movie play.

'''
2020/05/18 20:36:00 DEBUG : /: Lookup: name="Capone (2020).mkv"
2020/05/18 20:36:00 DEBUG : /: >Lookup: node=Capone (2020).mkv, err=
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: Attr:
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: >Attr: a=valid=1s ino=0 size=4134516494 mode=-rw-rw-r--, err=
2020/05/18 20:36:00 DEBUG : /: Lookup: name="Capone (2020).mkv"
2020/05/18 20:36:00 DEBUG : /: >Lookup: node=Capone (2020).mkv, err=
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: Attr:
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: >Attr: a=valid=1s ino=0 size=4134516494 mode=-rw-rw-r--, err=
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: >Open: fd=Capone (2020).mkv (r), err=
2020/05/18 20:36:00 DEBUG : Capone (2020).mkv: >Open: fh=&{Capone (2020).mkv (r)}, err=
2020/05/18 20:36:00 DEBUG : &{Capone (2020).mkv (r)}: Flush:
2020/05/18 20:36:00 DEBUG : &{Capone (2020).mkv (r)}: >Flush: err=
2020/05/18 20:36:00 DEBUG : &{Capone (2020).mkv (r)}: Release:
2020/05/18 20:36:00 DEBUG : &{Capone (2020).mkv (r)}: >Release: err=
2020/05/18 20:36:00 DEBUG : /: Attr:
2020/05/18 20:36:00 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 20:36:01 DEBUG : : Statfs:
2020/05/18 20:36:01 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:02 DEBUG : : Statfs:
2020/05/18 20:36:02 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:03 DEBUG : : Statfs:
2020/05/18 20:36:03 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:03 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:03 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: >Open: fd=The Irishman (2019).mkv (r), err=
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: >Open: fh=&{The Irishman (2019).mkv (r)}, err=
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: Flush:
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: >Flush: err=
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: Release:
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: >Release: err=
2020/05/18 20:36:03 DEBUG : /: Attr:
2020/05/18 20:36:03 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: >Open: fd=The Irishman (2019).mkv (r), err=
2020/05/18 20:36:03 DEBUG : The Irishman (2019).mkv: >Open: fh=&{The Irishman (2019).mkv (r)}, err=
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: Flush:
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: >Flush: err=
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: Release:
2020/05/18 20:36:03 DEBUG : &{The Irishman (2019).mkv (r)}: >Release: err=
2020/05/18 20:36:04 DEBUG : : Statfs:
2020/05/18 20:36:04 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:05 DEBUG : : Statfs:
2020/05/18 20:36:05 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:06 DEBUG : : Statfs:
2020/05/18 20:36:06 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:07 DEBUG : : Statfs:
2020/05/18 20:36:07 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:08 DEBUG : : Statfs:
2020/05/18 20:36:08 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:08 DEBUG : /: Attr:
2020/05/18 20:36:08 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 20:36:08 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:08 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:08 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:08 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: >Open: fd=The Irishman (2019).mkv (r), err=
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: >Open: fh=&{The Irishman (2019).mkv (r)}, err=
2020/05/18 20:36:08 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=131072, offset=0
2020/05/18 20:36:08 DEBUG : The Irishman (2019).mkv: ChunkedReader.openRange at 0 length 67108864
2020/05/18 20:36:09 DEBUG : : Statfs:
2020/05/18 20:36:09 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:09 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:09 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:09 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:09 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:09 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:09 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=131072, err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=131072, offset=131072
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=131072, err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=131072, offset=262144
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=131072, err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=131072, offset=393216
2020/05/18 20:36:10 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:10 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:10 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:10 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: >Open: fd=The Irishman (2019).mkv (r), err=
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: >Open: fh=&{The Irishman (2019).mkv (r)}, err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=69632, offset=7298637824
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.openRange at 0 length 67108864
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=131072, err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=131072, offset=524288
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=131072, err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Flush:
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Flush: err=
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: Release:
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ReadFileHandle.Release closing
2020/05/18 20:36:10 DEBUG : &{The Irishman (2019).mkv (r)}: >Release: err=
2020/05/18 20:36:10 DEBUG : : Statfs:
2020/05/18 20:36:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ReadFileHandle.seek from 0 to 7298637824 (fs.RangeSeeker)
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.RangeSeek from 0 to 7298637824 length -1
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at -1 length 4096 chunkOffset 7298637824 chunkSize 67108864
2020/05/18 20:36:10 DEBUG : The Irishman (2019).mkv: ChunkedReader.openRange at 7298637824 length 67108864
2020/05/18 20:36:11 DEBUG : : Statfs:
2020/05/18 20:36:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:12 DEBUG : : Statfs:
2020/05/18 20:36:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 7298641920 length 8192 chunkOffset 7298637824 chunkSize 67108864
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 7298650112 length 16384 chunkOffset 7298637824 chunkSize 67108864
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 7298666496 length 32768 chunkOffset 7298637824 chunkSize 67108864
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 7298699264 length 65536 chunkOffset 7298637824 chunkSize 67108864
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 7298764800 length 131072 chunkOffset 7298637824 chunkSize 67108864
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=69632, err=
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=69632, offset=7298707456
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=66246, err=
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: Flush:
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: >Flush: err=
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: Release:
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ReadFileHandle.Release closing
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: >Release: err=
2020/05/18 20:36:12 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:12 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:12 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:12 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: >Open: fd=The Irishman (2019).mkv (r), err=
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: >Open: fh=&{The Irishman (2019).mkv (r)}, err=
2020/05/18 20:36:12 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=69632, offset=4096
2020/05/18 20:36:12 DEBUG : The Irishman (2019).mkv: ChunkedReader.openRange at 0 length 67108864
2020/05/18 20:36:13 DEBUG : : Statfs:
2020/05/18 20:36:13 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: waiting for in-sequence read to 4096 for 5ms
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: aborting in-sequence read wait, off=4096
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: failed to wait for in-sequence read to 4096
2020/05/18 20:36:13 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:13 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:13 DEBUG : /: Lookup: name="The Irishman (2019).mkv"
2020/05/18 20:36:13 DEBUG : /: >Lookup: node=The Irishman (2019).mkv, err=
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: Attr:
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: >Attr: a=valid=1s ino=0 size=7298773702 mode=-rw-rw-r--, err=
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: Open: flags=OpenReadOnly
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: Open: flags=O_RDONLY
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: >Open: fd=The Irishman (2019).mkv (r), err=
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: >Open: fh=&{The Irishman (2019).mkv (r)}, err=
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: Flush:
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: >Flush: err=
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: Release:
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: >Release: err=
2020/05/18 20:36:13 DEBUG : /: Attr:
2020/05/18 20:36:13 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=69632, err=
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: Read: len=131072, offset=73728
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 67108864
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: >Read: read=131072, err=
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: Flush:
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: >Flush: err=
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: Release:
2020/05/18 20:36:13 DEBUG : The Irishman (2019).mkv: ReadFileHandle.Release closing
2020/05/18 20:36:13 DEBUG : &{The Irishman (2019).mkv (r)}: >Release: err=
2020/05/18 20:36:14 DEBUG : : Statfs:
2020/05/18 20:36:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:36:15 DEBUG : : Statfs:
2020/05/18 20:36:15 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
'''
It is very odd. Service always remains upp

'''
● movies.service - Google Movies Drive (rclone)
Loaded: loaded (/etc/systemd/system/movies.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2020-05-18 18:54:40 AEST; 1h 43min ago
Main PID: 769 (rclone)
Tasks: 20 (limit: 4915)
CGroup: /system.slice/movies.service
└─769 /usr/bin/rclone mount --user-agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36 --config=/home/plex/.config/rclone/rclone.conf --log-file=/logs/rcmovies.txt --log-level

May 18 18:54:40 plex systemd[1]: movies.service: AssertPathIsDirectory=/mnt/movies succeeded.
May 18 18:54:40 plex systemd[1]: movies.service: Passing 0 fds to service
May 18 18:54:40 plex systemd[1]: movies.service: About to execute: /usr/bin/rclone mount '--user-agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36' --config=/home/plex/.config/rclone/r
May 18 18:54:40 plex systemd[1]: movies.service: Forked /usr/bin/rclone as 769
May 18 18:54:40 plex systemd[1]: movies.service: Changed dead -> running
May 18 18:54:40 plex systemd[1]: movies.service: Job movies.service/start finished, result=done
May 18 18:54:40 plex systemd[1]: Started Google Movies Drive (rclone).
May 18 18:54:40 plex systemd[769]: movies.service: Executing: /usr/bin/rclone mount '--user-agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36' --config=/home/plex/.config/rclone/rclone

Whilst one mount is inaccesable I can view other rclone mounts as expected..

9

for more info.

I can run Plex accessing the mount with mutiple various movies , tv shows over and over.and see the rclone accessing the movie details , the filename, movies name etc.. and when i play it.. I can change movies, stop start over and over.

It only appears to be when I leave the mount without action that it fails...

10

Can you link the full log on pastebin/drive/smoething.

11

Here is a link to the logs

12

Did you stop it?

2020/05/18 20:47:27 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/05/18 20:47:27 DEBUG : rclone: Version "v1.51.0" finishing with parameters ["/usr/bin/rclone" "mount" "--user-agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36" "--config=/home/plex/.config/rclone/rclone.conf" "--log-file=/logs/rcmovies.txt" "--log-level" "DEBUG" "--allow-other" "--allow-non-empty" "--checkers" "4" "--umask" "002" "--buffer-size" "32M" "--dir-cache-time" "72h" "--drive-chunk-size" "32M" "--vfs-read-chunk-size" "64M" "--vfs-read-chunk-size-limit" "off" "--vfs-cache-mode" "writes" "boggy-plex-movies:/" "/mnt/movies"]
2020/05/18 20:47:27 DEBUG : cache cleaner exiting

"--allow-non-empty" is bad as it allows for over mounting and should not be used.

--checkers" "4" does nothing on a mount and can be removed.

13

I did stop the mount before i posted the logs.

I just added the --allow-non-empty as it had an error saying to add it.

The issues was there also before I added the --allow-non-empty , so this hasn't changed the issues from what I can see.

14

You over mounted something. If you had files in there and you mount with that, you lose the files that were there as you are hiding them. You'd want to clean the directory out as your mount directory should be empty.

Your log shows the mount continues to work so I'm not sure what you are seeing as the logs show it polls properly and the debug looks fine.

You can check by grepping for something like:

grep "Google drive root '': Checking for changes on remote" rcmovies.txt

and you can see it polls every minute and the statfs happens every second as expected.

15

Thanks Animosity.

The \mnt\movies folder is empty, and is only used for the mount.

The mount services always remain running without errors. The rclone logs never show a physical error wither. journalctl never shows an error, I just lose the ability to get into the mount. I can normally run a "ls" on the directory and get a result of the files included, but once this problem occurs, I do not get a directory listing until it resolves itself.

As mentioned, I can go into the other mounts whilst one is recovering..

16

Not trying to argue, but if you need to use allow-non-empty, it has something in it.

Is there a time in the debug log you shared that it happened? Is your system pegged on CPU/memory or something else when that occurs? Are you restarting the mount to correct or just waiting?

What does journalctl for the service say when you experience the problem?

felix@gemini:~$ journalctl -u rclone -b
-- Logs begin at Mon 2020-05-04 17:22:20 EDT, end at Mon 2020-05-18 08:15:36 EDT. --
May 17 07:22:04 gemini systemd[1]: Starting RClone Service...
May 17 07:22:06 gemini systemd[1]: Started RClone Service.

Thats my journal from boot.

17

All Good Animosity.. Appreciate your time and knowledge.. I have much to learn

I saw an error in logs somewhere the other day, I cannot remember, that mention an error with allow-non-empty, so I thought I would give it a go.. I have never used the directory location to store any files, and the mount point was created fresh.

for the debug log, I presume you mean the one associated with the mount, and if so , this is what I see when the mount stops working.

2020/05/18 20:30:17 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:17 DEBUG : /: Attr:
2020/05/18 20:30:17 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 20:30:17 DEBUG : /: Lookup: name="Agent Jade Black (2020).mp4"
2020/05/18 20:30:18 DEBUG : : Statfs:
2020/05/18 20:30:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 20:30:19 DEBUG : : Statfs:
2020/05/18 20:30:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899652321 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=

I was using plex, I got to select a movie, this time Agent Jade Black, this is selecting the movie from the home page.. If the DEBUG shows this, without any further details I know it if failing. I wait about 60 seconds and it is back on.

18

You'd want to share the whole debug log for the time as the clip you are shared looks like a good file lookup that returned.

Did you miss my journalctl question? You'd want to have the problem and share the debug logs and jouranctl and share the time period when the error happened to see what we can find.

19

thanks. THe previous log is what I see when it fails.. The Statfs continues until the mount returns.

This is how it normally looks when all working

2020/05/18 22:27:24 DEBUG : Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv: Open: flags=OpenReadOnly
2020/05/18 22:27:24 DEBUG : Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv: Open: flags=O_RDONLY
2020/05/18 22:27:24 DEBUG : Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv: >Open: fd=Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv (r), err=
2020/05/18 22:27:24 DEBUG : Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv: >Open: fh=&{Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv (r)}, err=
2020/05/18 22:27:24 DEBUG : &{Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv (r)}: Flush:
2020/05/18 22:27:24 DEBUG : &{Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv (r)}: >Flush: err=
2020/05/18 22:27:24 DEBUG : &{Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv (r)}: Release:
2020/05/18 22:27:24 DEBUG : &{Birds Of Prey (and The Fantabulous Emancipation Of One Harley Quinn) (2020).mkv (r)}: >Release: err=
2020/05/18 22:27:25 DEBUG : : Statfs:
2020/05/18 22:27:25 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899650406 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 22:27:26 DEBUG : : Statfs:
2020/05/18 22:27:26 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899650406 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 22:27:27 DEBUG : : Statfs:
2020/05/18 22:27:27 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899650406 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 22:27:28 DEBUG : : Statfs:
2020/05/18 22:27:28 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899650406 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 22:27:28 DEBUG : /: Lookup: name="Capone (2020).mkv"
2020/05/18 22:27:28 DEBUG : /: >Lookup: node=Capone (2020).mkv, err=
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: Attr:
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: >Attr: a=valid=1s ino=0 size=4134516494 mode=-rw-rw-r--, err=
2020/05/18 22:27:28 DEBUG : /: Lookup: name="Capone (2020).mkv"
2020/05/18 22:27:28 DEBUG : /: >Lookup: node=Capone (2020).mkv, err=
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: Attr:
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: >Attr: a=valid=1s ino=0 size=4134516494 mode=-rw-rw-r--, err=
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: Open: flags=OpenReadOnly
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: Open: flags=O_RDONLY
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: >Open: fd=Capone (2020).mkv (r), err=
2020/05/18 22:27:28 DEBUG : Capone (2020).mkv: >Open: fh=&{Capone (2020).mkv (r)}, err=
2020/05/18 22:27:28 DEBUG : &{Capone (2020).mkv (r)}: Flush:
2020/05/18 22:27:28 DEBUG : &{Capone (2020).mkv (r)}: >Flush: err=
2020/05/18 22:27:28 DEBUG : &{Capone (2020).mkv (r)}: Release:
2020/05/18 22:27:28 DEBUG : &{Capone (2020).mkv (r)}: >Release: err=
2020/05/18 22:27:28 DEBUG : /: Attr:
2020/05/18 22:27:28 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 22:27:29 DEBUG : Google drive root '': Checking for changes on remote
2020/05/18 22:27:29 DEBUG : : Statfs:
2020/05/18 22:27:29 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899650406 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 22:27:30 DEBUG : : Statfs:
2020/05/18 22:27:30 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:266899650406 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2020/05/18 22:27:30 DEBUG : /: Lookup: name="LEGO DC - Shazam! Magic And Monsters (2020).mkv"
2020/05/18 22:27:30 DEBUG : /: >Lookup: node=LEGO DC - Shazam! Magic And Monsters (2020).mkv, err=
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: Attr:
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: >Attr: a=valid=1s ino=0 size=3366895756 mode=-rw-rw-r--, err=
2020/05/18 22:27:30 DEBUG : /: Lookup: name="LEGO DC - Shazam! Magic And Monsters (2020).mkv"
2020/05/18 22:27:30 DEBUG : /: >Lookup: node=LEGO DC - Shazam! Magic And Monsters (2020).mkv, err=
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: Attr:
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: >Attr: a=valid=1s ino=0 size=3366895756 mode=-rw-rw-r--, err=
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: Open: flags=OpenReadOnly
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: Open: flags=O_RDONLY
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: >Open: fd=LEGO DC - Shazam! Magic And Monsters (2020).mkv (r), err=
2020/05/18 22:27:30 DEBUG : LEGO DC - Shazam! Magic And Monsters (2020).mkv: >Open: fh=&{LEGO DC - Shazam! Magic And Monsters (2020).mkv (r)}, err=
2020/05/18 22:27:30 DEBUG : &{LEGO DC - Shazam! Magic And Monsters (2020).mkv (r)}: Flush:
2020/05/18 22:27:30 DEBUG : &{LEGO DC - Shazam! Magic And Monsters (2020).mkv (r)}: >Flush: err=
2020/05/18 22:27:30 DEBUG : &{LEGO DC - Shazam! Magic And Monsters (2020).mkv (r)}: Release:
2020/05/18 22:27:30 DEBUG : &{LEGO DC - Shazam! Magic And Monsters (2020).mkv (r)}: >Release: err=
2020/05/18 22:27:30 DEBUG : /: Attr:
2020/05/18 22:27:30 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2020/05/18 22:27:31 DEBUG : : Statfs:

As for Journalctl logs for the service, they do not say that is stops and starts.. it is always running.

20

If you can share the output rather than telling me what it says, that helps more.

Every log you've shared so far looks good and working with no errors.