Radarr and rclone mount

athelmil · July 27, 2019, 7:43pm

So for the past few months ive been utilizing radarr and sonarr pointed directly at the rclone mount. i understand the pros and cons of doing that vs using unionfs and copy/move commands.

Anyways recently radarr and sonarr have been doing something odd. my download program downloads the file, extracts it if needed then radarr/sonarr copies the file and as it finishes there is a spike in the network use and then i notice that it downloads/uploads the file all over again. Any ideas? nothing has changed in my configs ive been using the past few months. latest sonarr/radarr/rclone fwiw

Animosity022 · July 27, 2019, 8:06pm

rclone version shows what?
what's your rclone.conf with keys and passwords.
what's your mount command look like?
Can you recreate the issue and share a log?

athelmil · July 27, 2019, 8:11pm

version is 1.48
as far as conf goes im not sure what you want. but i have a regular remote and a crypt remote, of that remote. everything is pointed at the crypt

[Unit]
Description=Google Drive (rclone)
AssertPathIsDirectory=/gsuite
Wants=network-online.target
After=network-online.target
 
[Service]
Type=simple
ExecStart=/usr/bin/rclone mount crypt: /gsuite \
        --config=/root/.config/rclone/rclone.conf \
        --allow-other \
        --buffer-size 128M \
        --dir-cache-time 72h \
        --drive-chunk-size 32M \
        --umask 002 \
        --vfs-read-chunk-size 128M \
        --vfs-read-chunk-size-limit off \
        --user-agent user
ExecStop=/bin/fusermount -u /gsuite
Restart=always
RestartSec=10
 
[Install]
WantedBy=default.target

i have my own client_id and secret.

The problem is constant so no need to replicate per say.

What logs are you interested in? rclone?sonarr/radarr? honestly the sonarr/radarr logs arent informative

athelmil · July 27, 2019, 8:29pm

also fwiw here is a screenshot of my grafana reports.

https://gyazo.com/64e725d27c1f0d57f1d187e8a81ff578

You can see the green is upload and it dips then all of a sudden there is a spike in download it levels off and continues. And it almost actually matches all away across for download and upload speed.
.
I also included the total bandwidth used. i moved an 8gb file total upload was about 18gb and total download was 8.2 gb. the upload discrepancy is because of how grafana reports in time blocks. ive got some other stuff uploading that accounts for the extra bandwidth.

Animosity022 · July 27, 2019, 8:32pm

rclone logs. If you run with -vv and capture the issue, we can see what's going on.

athelmil · July 29, 2019, 5:49pm

sorry it took so long. i had to create a log file and comb through it.

So for the first part of the upload

This is the output

2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Write: len=4096, offset=8205242368
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Write: len=4096, offset=8205246464
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Write: len=4096, offset=8205250560
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Write: len=4096, offset=8205254656
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Write: len=4096, offset=8205258752
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Write: len=4096, offset=8205262848
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Write: written=4096, err=<nil>```

then i get a chunk of text when it ends

2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Setattr: a=Setattr [ID=0x1e94cf Node=0x9 Uid=1000 Gid=1000 Pid=1445] atime=2019-07-29 19:26:43.773955485 +0200 CEST mtime=2017-05-12 09:19:45.1755544 +0200 CEST handle=INVALID-0x0
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Setattr: err=<nil>
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Attr: 
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Attr: a=valid=1s ino=0 size=8205315206 mode=-rw-rw-r--, err=<nil>
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Setattr: a=Setattr [ID=0x1e94d0 Node=0x9 Uid=1000 Gid=1000 Pid=1445] mode=-rw-r--r-- handle=INVALID-0x0
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Setattr: err=<nil>
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Attr: 
2019/07/29 19:31:11 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Attr: a=valid=1s ino=0 size=8205315206 mode=-rw-rw-r--, err=<nil>
2019/07/29 19:31:11 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Flush: 
2019/07/29 19:31:12 DEBUG : : Statfs: 
2019/07/29 19:31:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:267714036898 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/07/29 19:31:13 DEBUG : : Statfs: 
2019/07/29 19:31:13 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:267714036898 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/07/29 19:31:14 DEBUG : : Statfs:

Those last two lines repeat for a bit and then this

2019/07/29 19:31:56 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Size and modification time the same (differ by -518.63µs, within tolerance 1ms)
2019/07/29 19:31:56 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: File.applyPendingModTime OK
2019/07/29 19:31:56 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Flush: err=<nil>
2019/07/29 19:31:56 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: Release: 
2019/07/29 19:31:56 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: WriteFileHandle.Release nothing to do
2019/07/29 19:31:56 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (w)}: >Release: err=<nil>
2019/07/29 19:31:56 DEBUG : /: Lookup: name="Movies"
2019/07/29 19:31:56 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2019/07/29 19:31:56 DEBUG : Movies/: Attr: 
2019/07/29 19:31:56 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/07/29 19:31:56 DEBUG : : Statfs: 
2019/07/29 19:31:56 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:267714036898 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2019/07/29 19:31:57 DEBUG : /: Lookup: name="Movies"
2019/07/29 19:31:57 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/: Attr: 
2019/07/29 19:31:57 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/: Lookup: name="Moonlight (2016)"
2019/07/29 19:31:57 DEBUG : Movies/: >Lookup: node=Movies/Moonlight (2016)/, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Attr: 
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv.partial~"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Attr: 
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Attr: a=valid=1s ino=0 size=8205315206 mode=-rw-rw-r--, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Link: req=Link [ID=0x1e9510 Node=0x9 Uid=1000 Gid=1000 Pid=1445] node 10 to "Moonlight (2016).mkv", old=Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Link: new=<nil>, err=function not implemented
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Open: flags=OpenReadOnly
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: Open: flags=O_RDONLY
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Open: fd=Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (r), err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: >Open: fh=&{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (r)}, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Lookup: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Lookup: node=<nil>, err=no such file or directory
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: Create: name="Moonlight (2016).mkv"
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv: Open: flags=O_RDWR|O_CREATE|O_EXCL
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv: >Open: fd=Movies/Moonlight (2016)/Moonlight (2016).mkv (w), err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/: >Create: node=Movies/Moonlight (2016)/Moonlight (2016).mkv, handle=&{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}, err=<nil>
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv: Attr: 
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (r)}: Read: len=131072, offset=0
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.openRange at 0 length 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (r)}: >Read: read=131072, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (r)}: Read: len=131072, offset=131072
2019/07/29 19:31:57 DEBUG : Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 536870912
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv.partial~ (r)}: >Read: read=131072, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: Write: len=4096, offset=0
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: Write: len=4096, offset=4096
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: Write: len=4096, offset=8192
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: Write: len=4096, offset=12288
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: >Write: written=4096, err=<nil>
2019/07/29 19:31:57 DEBUG : &{Movies/Moonlight (2016)/Moonlight (2016).mkv (w)}: Write: len=4096, offset=16384

Animosity022 · July 29, 2019, 5:51pm

Can you link the whole log rather than pieces?

athelmil · July 29, 2019, 5:52pm

its pretty long >.>

Animosity022 · July 29, 2019, 5:53pm

It's easier to see the log rather than ask a bunch of questions for specific things that I want to see.

athelmil · July 29, 2019, 5:57pm

okie dokie. the log file is about 1gb in size. ill have to upload it so its easier to share

athelmil · July 29, 2019, 6:03pm

Animosity022 · July 29, 2019, 6:17pm

When it is done, are you seeing the partial file and the final file as well?

athelmil · July 29, 2019, 6:28pm

just the final file. the partial file appears once its done the first time. then the second time the partial is gone and then final file is whats left

Animosity022 · July 29, 2019, 6:28pm

I was hoping to see something a bit more obvious, but what I think it happening is that the way Sonarr and Radarr work is they make a copy and use the partial and once the copy is complete, they rename it and I think that is what you are seeing as the root cause of the issue.

You should be able to address it I believe with use --vfs-cache-mode writes

and I think that would address it. I wanted to see the full log in case something was different in there or there was a message hiding. I tried playing around with your same mount and didn't have much luck.

athelmil · July 29, 2019, 6:31pm

yeah i was thinking it was something like that. I have something similar happen when i use radarr/sonarr with zipped files. the autoextract happens and it immediately starts uploading the incomplete file. basically ends up uploading twice.

the flag you recommend. just add it to my existing service file?

Animosity022 · July 29, 2019, 6:34pm

Yes but there a few things to think about with it and you may want to adjust this.

There are the flags that go along with it:

--cache-dir string                   Directory rclone will use for caching.
--vfs-cache-max-age duration         Max age of objects in the cache. (default 1h0m0s)
--vfs-cache-mode string              Cache mode off|minimal|writes|full (default "off")
--vfs-cache-poll-interval duration   Interval to poll the cache for stale objects. (default 1m0s)
--vfs-cache-max-size int             Max total size of objects in the cache. (default off)

The cache-dir is the one to think about as that is where it will temporarily write to disk for the files. You want to make sure this is a good spot that isn't going to get full

The rest of the defaults are probably ok as it's telling you that it'll keep the files for 1 hour by default before deleting them and it does that clean up every 1 minute.

Basically what happens is that it writes to the cache-dir area immediately when it copies the file and once the local copy is done, it immediately uploads to your remote. It tracks the renames and such as I used it with Sonarr/Radarr before I moved to mergerfs in own personal setup.

athelmil · July 29, 2019, 6:38pm

ok so i have to also add those appropriate strings.
mind giving me a recommended config?

athelmil · July 29, 2019, 6:39pm

rclone mount crypt: /gsuite -vv --allow-other --buffer-size 1G --dir-cache-time 72h --drive-chunk-size 128M --umask 002 --vfs-read-chunk-size 512M --vfs-read-chunk-size-limit off --vfs-cache-mode writes --cache-dir /cache --vfs-cache-max-age --vfs-cache-poll-interval --vfs-cache-max-size 250G im good with those defaults

Animosity022 · July 29, 2019, 6:40pm

Yep, so you are only adding in vfs-cache-mode and cache-dir so that's I think that's just fine!

athelmil · July 29, 2019, 6:41pm

just to make sure. do i need to add --vfs-cache-max-age --vfs-cache-poll-interval if i plan on using the defaults?