Radarr writes to cache remote twice

rocinante · July 25, 2019, 11:39pm

What is the problem you are having with rclone?

Hey guys, so I started after months of not having this particular issue getting a weird thing happening all of a sudden with radarr and only radarr. Sonarr works just fine. I have a cache remote set up that both radarr and sonarr point to directly and write to. Normally, radarr processes the file, writes to cache locally and then immediately sends it to gdrive. The problem I started having now is that radarr does this twice. It processes file, writes to cache locally, sends to gdrive and does the same thing again one more time before the file is done processing. I don't have duplicate uploads on gdrive and as I said, sonarr doesn't do this. Attaching a log I captured after the first upload and inbetween radarr's second run. I'd appreciate if you could have a look at it.

I've also deleted and readded my cache remote in rclone and reinstalled radarr with a clean install. Still happens. Didn't happen two or three days ago, I monitor rclone often while I add stuff.
Thanks and let me know if you need more info.

Blockquote
2019/07/26 01:24:57 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: Sending chunk 528482304 length 5038732
2019/07/26 01:24:58 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: put: uploaded to remote fs
2019/07/26 01:24:58 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: put: added to cache
2019/07/26 01:24:58 DEBUG : Movies/Critters Attack! (2019): cache: expired Movies/Critters Attack! (2019)
2019/07/26 01:24:58 DEBUG : Movies/Critters Attack! (2019): cache: expired Movies
2019/07/26 01:24:58 DEBUG : Movies/Critters Attack! (2019): cache: expired
2019/07/26 01:24:58 INFO : Movies/Critters Attack! (2019): put: cache expired
2019/07/26 01:24:58 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: object hash cached: d069eeb6703413748123ca066cd4041e
2019/07/26 01:24:58 INFO : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: Copied (new)
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: updated ModTime: 2019-07-25 14:05:44 +0200 CEST
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: File.applyPendingModTime OK
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: transferred to remote
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~(0xc0000ca360): >close: err=
2019/07/26 01:24:59 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (rw)}: >Flush: err=
2019/07/26 01:24:59 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (rw)}: Release:
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~(0xc0000ca360): RWFileHandle.Release nothing to do
2019/07/26 01:24:59 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (rw)}: >Release: err=
2019/07/26 01:24:59 DEBUG : /: Lookup: name="Movies"
2019/07/26 01:24:59 DEBUG : /: >Lookup: node=Movies/, err=
2019/07/26 01:24:59 DEBUG : Movies/: Attr:
2019/07/26 01:24:59 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2019/07/26 01:24:59 DEBUG : /: Lookup: name="Movies"
2019/07/26 01:24:59 DEBUG : /: >Lookup: node=Movies/, err=
2019/07/26 01:24:59 DEBUG : Movies/: Attr:
2019/07/26 01:24:59 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2019/07/26 01:24:59 DEBUG : Movies/: Lookup: name="Critters Attack! (2019)"
2019/07/26 01:24:59 DEBUG : Movies/: >Lookup: node=Movies/Critters Attack! (2019)/, err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Attr:
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv.partial~"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~, err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: Attr:
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: >Attr: a=valid=1s ino=0 size=533521036 mode=-rw-r--r--, err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Link: req=Link [ID=0x1fd13 Node=0x3 Uid=1003 Gid=1003 Pid=29919] node 2 to "Critters Attack! (2019) DVD WiDE.mkv", old=Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Link: new=, err=function not implemented
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: Open: flags=OpenReadOnly
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: Open: flags=O_RDONLY
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: >Open: fd=Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (r), err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: >Open: fh=&{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (r)}, err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Lookup: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Lookup: node=, err=no such file or directory
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: Create: name="Critters Attack! (2019) DVD WiDE.mkv"
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv: Open: flags=O_RDWR|O_CREATE|O_EXCL
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv(0xc00016acc0): Opened existing cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv: >Open: fd=Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv (rw), err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/: >Create: node=Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv, handle=&{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv (rw)}, err=
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv: Attr:
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=
2019/07/26 01:24:59 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (r)}: Read: len=131072, offset=0
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.openRange at 0 length 134217728
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: moving offset set from 0 to 0
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: 0: chunk retry storage: 0
2019/07/26 01:24:59 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: 0: chunk retry storage: 1
2019/07/26 01:24:59 DEBUG : worker-0 <Critters Attack! (2019) DVD WiDE.mkv.partial~>: downloaded chunk 33554432
2019/07/26 01:25:00 DEBUG : worker-2 <Critters Attack! (2019) DVD WiDE.mkv.partial~>: downloaded chunk 67108864
2019/07/26 01:25:00 DEBUG : worker-1 <Critters Attack! (2019) DVD WiDE.mkv.partial~>: downloaded chunk 0
2019/07/26 01:25:00 DEBUG : worker-3 <Critters Attack! (2019) DVD WiDE.mkv.partial~>: downloaded chunk 100663296
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 2093056 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 3141632 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (r)}: >Read: read=131072, err=
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 4190208 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 5238784 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 6287360 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 7335936 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 8384512 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 9433088 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (r)}: Read: len=131072, offset=131072
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 10481664 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 11530240 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~ (r)}: >Read: read=131072, err=
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 12578816 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 13627392 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv.partial~: ChunkedReader.Read at 14675968 length 1048576 chunkOffset 0 chunkSize 134217728
2019/07/26 01:25:00 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv (rw)}: Write: len=4096, offset=0
2019/07/26 01:25:00 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv (rw)}: >Write: written=4096, err=
2019/07/26 01:25:00 DEBUG : &{Movies/Critters Attack! (2019)/Critters Attack! (2019) DVD WiDE.mkv (rw)}: Write: len=4096, offset=4096

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

1.48

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

Gdrive

ll0renz · August 2, 2019, 2:21pm

I'm not the only one!!!

I'm experiencing this issue as well, though I'm seeing it with Sonarr instead of Radarr. That makes me think we're looking at an rclone/GDrive issue not a local software issue. Maybe something with server-side-copy or renaming?

I'm running Sonarr in Docker, with the rclone mount on the host passed through to the Docker container. Sonarr can see everything and create files/folders without issue.

To add more details, both Sonarr & Radarr try to be very conservative with copying files. They make a backup duplicate of the file to be imported in the source and instead of moving/copying the file directly, they write a temp file to the new location, then rename it to the final desired filename.

From my perspective, I see Sonarr create a file on the mount with the desired filename + a .partial~ extension. I can watch that file grow to the correct size, and outgoing net traffic confirms X amount has been transferred.

Then, INSTEAD of seeing the .partial~ file renamed to regular filename, that file remains in the mount and a copy bearing the correct name appears. It grows to the correct size but while it does, I get matching download AND upload traffic, indicating rclone is downloading and re-uploading a copy under the new filename instead of being renamed in place. Once that move completes, the .partial~ file disappears and everyone's happy, except it took 3X the bandwidth than it should've.

I'm still not sure if this is a Sonarr or rclone issue, because if I execute a shell inside the Docker container, I can manually move/rename files on the mount without issue. It seem to be only Sonarr/Radarr's copy/rename strategy that triggers the problem.

Animosity022 · August 2, 2019, 2:29pm

A log with -vv would be the best to reproduce the issue and the mount command as well.

ll0renz · August 2, 2019, 3:44pm

Yup, gladly

rclone mount --allow-other --cache-writes GSuite-Crypt-Main:/ /home/USER/PlexMain -v

Very simple mount command, mounting a GSuite > Cache > Crypt remote though I was using straight GSuite > Crypt earlier and it was producing the same issue.

To do a test, I had Sonarr upgrade an existing episode file, which should mean one move/rename of the original to the Recycling folder (within the mount), one straight file-upload to a *.partial~ file, then one move/rename of that *.partial~ file to the original filename.

Log posted here w/ some comments and removal of the many thousands of upload/download messages: https://pastebin.com/jBhzNxqj

Thanks for taking a look!

Animosity022 · August 2, 2019, 3:55pm

Huge chunks of the log are missing unfortunately so hard to read through that log. Can you share the whole thing rather than clipping pieces out?

ll0renz · August 2, 2019, 3:58pm

Sorry, was trying to be helpful. It was like 75MB of log file, 99% of it just the upload/write messages so I though it would be easier to read with those dups cut out. I'll generate another and post it in it's entirety.

Animosity022 · August 2, 2019, 4:13pm

I can see few things but not sure how/if they are causing the issue.

I'm assuming you have use hard links on as I can see this:

VD.mkv", old=TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Link: new=<nil>, err=function not implemented
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"

That is Radarr trying to hard link a file rather than copying it. That should be this and you can turn it off if you are using a rclone mount:

The other part I can see in the logs is that it copies the partial and I would assume Radarr should release the partial file and rename it but it seems to not find the file and copies it.

2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Link: req=Link [ID=0x25ad7 Node=0x35 Uid=1001 Gid=1001 Pid=19465] node 61 to "The Brady Bunch - S01E01 - The Honeymoon DVD.mkv", old=TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Link: new=<nil>, err=function not implemented
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~: Open: flags=OpenReadOnly
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~: Open: flags=O_RDONLY
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~: >Open: fd=TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~ (r), err=<nil>
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~: >Open: fh=&{TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~ (r)}, err=<nil>
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Lookup: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Lookup: node=<nil>, err=no such file or directory
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: Create: name="The Brady Bunch - S01E01 - The Honeymoon DVD.mkv"
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv: Open: flags=O_RDWR|O_CREATE|O_EXCL
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv: >Open: fd=TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv (w), err=<nil>
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/: >Create: node=TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv, handle=&{TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv (w)}, err=<nil>
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv: Attr:
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2019/08/02 15:07:59 DEBUG : &{TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~ (r)}: Read: len=131072, offset=0
2019/08/02 15:07:59 DEBUG : TV Shows/The Brady Bunch/Season 1/The Brady Bunch - S01E01 - The Honeymoon DVD.mkv.partial~: ChunkedReader.openRange at 0 length 134217728
2019/08/02 15:07:59 DEBUG : accckdc38dflkcd8uh8ldbapg0/i6e45gauh43eon95vj316d6ivc/he3or53693ntstb81clsc0iaqc/7oj4skuc3ouj8seekr4h0ip8d3rulaadr68isa3sp044al8eje7vrtplu4lmme6s57a038v5gfnfe7nv2et8pi51idqmeotvg3anh8g: moving offset set from 0 to 0
2019/08/02 15:07:59 DEBUG : accckdc38dflkcd8uh8ldbapg0/i6e45gauh43eon95vj316d6ivc/he3or53693ntstb81clsc0iaqc/7oj4skuc3ouj8seekr4h0ip8d3rulaadr68isa3sp044al8eje7vrtplu4lmme6s57a038v5gfnfe7nv2et8pi51idqmeotvg3anh8g: 0: chunk retry storage: 0

I am also assuming you mean Sonarr rather than Radarr we're talking about TV shows rather than movies.

Animosity022 · August 2, 2019, 4:22pm

Instead of cache-writes can you give a test with --cache-tmp-upload instead?

ll0renz · August 2, 2019, 4:53pm

Correct, I'm definitely looking at Sonarr here. I turned off the hard-linking feature in Sonarr but still got the same behavior.

Got a full log posted here ~60MB, this is with --cache-uploads.

Partial success with the --cache-temp-upload-path! Moving a file from the main dir to the recycled directory still produced a download/upload copy, but Sonarr uploading and renaming the .partial~ file to the correct file name worked fine without the 3X bandwidth issue.

ll0renz · August 2, 2019, 5:05pm

Dang, I stand corrected. Using --cache-temp-upload-path works (I can see files accumulating in that location), but it ends up double the size of the file to be uploaded, and seems to upload both the .partial~ and original filename... then deletes the .partial~

Warmer it would seem, but still doing double bandwidth.

Animosity022 · August 2, 2019, 5:22pm

It should wait 15 seconds by default, but you may want to bump that up to like 15 minutes or something and let if finish doing all it's moving before it uploads:

https://rclone.org/cache/#cache-tmp-wait-time

ll0renz · August 2, 2019, 7:17pm

After toying around with this over the last few hours, I'm starting to believe more and more that it's a Sonarr/Docker issue, not a rclone one. I'm thinking Sonarr is looking at my Downloads and Media folders (which are separate Docker bind mounts) and is having an issue with that, rather than anything with rclone itself.

I'll keep investigating, thanks for your help with the analysis.

system · October 31, 2019, 7:17pm

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

Radarr writes to cache remote twice

What is the problem you are having with rclone?

What is your rclone version (output from rclone version)

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

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