Rclone moving files that are still being written

I am running Radarr (V3 dotnet), Sonarr (V3), NZBGet, and Rclone (all newest stable versions).
Ubuntu 20.04

I have a script that runs whenever a download is complete that is supposed to move the newly downloaded file to my Google Team Drive:
/usr/bin/rclone move /home/server/data/local gcrypt: --log-file $LOGFILE -vv --delete-empty-src-dirs --fast-list --exclude *.partial~ --fast-list --drive-stop-on-upload-limit

My issue is that my script starts moving the file before Sonarr/Radarr moves the whole file. I have read that Rclone is supposed to skip files that are still being written but that's not working in my case.

It usually only moves a few GB then deletes the file. Examples: 85 GB movie transferred only 5GB then deleted the rest, 5GB shows transfer a couple GB.

So now I have a bunch of corrupted files mixed in with non-corrupted files I need to go through.

The logs show everything is working as normal so I'm lost:

2020/08/25 16:15:01 DEBUG : rclone: Version "v1.52.3" starting with parameters ["/usr/bin/rclone" "move" "/home/server/data/local" "gcrypt:" "--log-file" "/home/server/rclonemove.log" "-vv" "--delete-empty-src->
2020/08/25 16:15:01 DEBUG : Using config file from "/home/server/.config/rclone/rclone.conf"
2020/08/25 16:15:04 DEBUG : dociument.docx: Skipping undecryptable file name: not an encrypted file - no ".bin" suffix
2020/08/25 16:15:08 DEBUG : Encrypted drive 'gcrypt:': Waiting for checks to finish
2020/08/25 16:15:08 DEBUG : Encrypted drive 'gcrypt:': Waiting for transfers to finish
2020/08/25 16:15:08 DEBUG : 20.apwEA/88.NbdHzwfs (7561)/189.Ugcuqp 1/175.ZnpTLIrE (4238) f26R29 Znp + QrFv + evyrL + NHoErL jROQY-3202C.zxI: Sending chunk 0 length 8388608
2020/08/25 16:15:09 DEBUG : 20.apwEA/88.NbdHzwfs (7561)/189.Ugcuqp 1/175.ZnpTLIrE (4238) f26R29 Znp + QrFv + evyrL + NHoErL jROQY-3202C.zxI: Sending chunk 8388608 length 8388608
... A BUNCH OF THESE LINES...
2020/08/25 16:16:03 DEBUG : 20.apwEA/88.NbdHzwfs (7561)/189.Ugcuqp 1/175.ZnpTLIrE (4238) f26R29 Znp + QrFv + evyrL + NHoErL jROQY-3202C.zxI: Sending chunk 1342177280 length 8388608
2020/08/25 16:16:03 INFO  :
Transferred:        1.258G / 3.733 GBytes, 34%, 23.411 MBytes/s, ETA 1m48s
Checks:                 0 / 1, 0%
Transferred:            0 / 1, 0%
Elapsed time:        55.0s
Checking:

Transferring:
 * XXXXXXXXXXXXXXXXXXXXXXXXXXXX: 33% /3.733G, 23.771M/s, 1m46s

This example was supposed to be 4.6GB so not much of a difference.

Help???

If the file was being actively written to while it transferring, rclone would notice that and print some messages like:

2020/08/25 19:39:01 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2020/08/25 19:39:01 DEBUG : fs cache: adding new entry for parent of "blah.mkv", "/home/felix/test"
2020/08/25 19:39:02 DEBUG : blah.mkv: Need to transfer - File not found at Destination
2020/08/25 19:39:02 DEBUG : blah.mkv: Sending chunk 0 length 1073741824
2020/08/25 19:39:06 ERROR : blah.mkv: Failed to copy: Post "https://www.googleapis.com/upload/drive/v3/files?alt=json&fields=id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails&supportsAllDrives=true&uploadType=resumable&upload_id=AAANsUl4jDI_QTNICFBnyKS2BMwsIPPWRTzkHmt54gK3ZsSkV2eEOhS8D_UfBh2D7f1obrDQIZItNsUqRkhyp_hrJaw": can't copy - source file is being updated (size changed from 1504953150 to 1530118974)
2020/08/25 19:39:06 ERROR : Attempt 1/3 failed with 1 errors and: Post "https://www.googleapis.com/upload/drive/v3/files?alt=json&fields=id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails&supportsAllDrives=true&uploadType=resumable&upload_id=AAANsUl4jDI_QTNICFBnyKS2BMwsIPPWRTzkHmt54gK3ZsSkV2eEOhS8D_UfBh2D7f1obrDQIZItNsUqRkhyp_hrJaw": can't copy - source file is being updated (size changed from 1504953150 to 1530118974)
2020/08/25 19:39:06 DEBUG : blah.mkv: Need to transfer - File not found at Destination
2020/08/25 19:39:07 DEBUG : blah.mkv: Sending chunk 0 length 1073741824
2020/08/25 19:39:07 ERROR : blah.mkv: Failed to copy: Post "https://www.googleapis.com/upload/drive/v3/files?alt=json&fields=id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails&supportsAllDrives=true&uploadType=resumable&upload_id=AAANsUncv22QuXOh6d35ESpYQnzsFE_kZNCU-izBnUKStTg05-7-WZmuss6ZE7ogW-fe-gI3I4pjF7-mEvf0Tkq4AksN9xmePQ": can't copy - source file is being updated (size changed from 2249835326 to 2543043390)
2020/08/25 19:39:07 ERROR : Attempt 2/3 failed with 1 errors and: Post "https://www.googleapis.com/upload/drive/v3/files?alt=json&fields=id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails&supportsAllDrives=true&uploadType=resumable&upload_id=AAANsUncv22QuXOh6d35ESpYQnzsFE_kZNCU-izBnUKStTg05-7-WZmuss6ZE7ogW-fe-gI3I4pjF7-mEvf0Tkq4AksN9xmePQ": can't copy - source file is being updated (size changed from 2249835326 to 2543043390)
2020/08/25 19:39:07 DEBUG : blah.mkv: Need to transfer - File not found at Destination
2020/08/25 19:39:08 DEBUG : blah.mkv: Sending chunk 0 length 1073741824

as an example.

I searched the logs and found one of those errors within 4,600 lines of thousands of uploads.

Is it possible that the incomplete file finishes uploading before Sonarr or Radarr writes again?

edit...

actually I don't think I did get any of those errors. These are all the errors from the log:

2020/08/25 01:48:16 ERROR : XXXXX/XXXXX/XXXXX/XXXXXX.XXX: Couldn't delete: remove /home/server/data/local/Movies/XXXXXXXX/XXXXXX.XXX: no such file or directory
2020/08/25 01:48:16 ERROR : Local file system at /home/server/data/local: not deleting directories as there were IO errors
2020/08/25 01:48:16 ERROR : Attempt 1/3 failed with 2 errors and: not deleting directories as there were IO errors
2020/08/25 01:48:23 ERROR : Attempt 2/3 succeeded

My understanding is that it writes from start to finish and doesn't just stop and pick up. It should be a constant write stream.

I tend to not do a move from my 'in flight' areas and only move on the completed area as the files are definitely done copying.

My setup is similar to what you did here: https://github.com/animosity22/homescripts

NZBGet has an incomplete folder and a complete folder. Sonarr/Radarr should get the file from the complete folder.

I have mergerfs setup so my local and cloud storage is combined the same way explained in the guide.

So once the file is finished downloading Sonarr or Radarr should stick it in the local folder (via mergerfs)
then the script should run (set to run on rename in Sonarr and Radarr) which should move it to Google then delete it.

I use hard links as the copies happen instantly since they just make a link but I have my items on the same disk.

Even with that setup, if Radarr is copying locally, it's a constant stream so that seems odd as Sonarr/Radarr noramlly don't stop writing when they are copying a file.

What are you moving? Are you moving just the completed area?

I am also using hardlinks which makes this odd. All my data is on the same drive (VPS SSD)

I am only moving what is imported by sonarr and radarr which should just be the finished renamed files.

I think I'll just stick some code in my script that makes sure nothing has been accessed for a couple minutes before I let rclone move it.

use the --min-age and set it to 1m or 5m.

Do a test to see if you're hardlinking in your setup.

Go to sonarr or radarr and do a manual import on a file that is at least 2Gb in size, from your downloads folder. If it imports and says completed within 2 seconds, you are hardlinking. If it takes longer than that, it's copying the file and deleting it. If it's doing that, the #1 cause is how you setup your volumes both on the host and in the container. Each volume binding in a container is 1 filesystem and 1 device. You can't hardlink across devices or file systems. So inside the container, if you have /downloads and /media, then it's going to be 2 different devices and filesystems and be forced to copy. To fix this, you will need to change your structure so both downloads and media folder are inside a directory together, like /data/media and /data/downloads. Then just bind ./data:/data` in sonarr/radarr

Something isn't happening the way you think then.

If you are using hard links, they happen instantly and wouldn't create the files being written to issue.

I would figure out what's going on and correct it rather than band aiding, but the min-age would band aid it.

I do have really high CPU usage which might cause issues with copying???

This is probably a dumb question but does the --min-age use the last access time, the file creation date, or something else?

I have Sonarr and Radarr set to change the date on the file. I don't think that should matter but thought I should ask.

Yeah you're not hardlinking, that's the real issue. I edited my last reply with how to fix it.

I am not running docker so I don't have any containers.

My structure is:
home/server/data/downloads/complete
home/server/data/downloads/incomplete
home/server/data/local
home/server/data/cloud

home/server/mergerfs

data is a mounted drive
cloud is where rclone is mounted

mergerfs merges local and cloud utilizing local first

The same concept will still apply with mergerfs.

If sonarr/radarr uses the mergerfs mount than you must have your branches setup like
home/server/data/local:rw
home/server/data/cloud:nc
home/server/mergerfs
create=ff

Your downloads folder must be inside home/server/data/local for you to be able to hardlink. You're structure shows that you are likely adding downloads/incomplete and downloads/complete as 2 branches to merge together, that's not going to work.

I ran into this same thing when starting out with this setup. Look at animosity022's github repo for an example that hardlinks.

An alternative to using mergerfs would be using the rclone union remote which recently improved. You'll have the same issue if you keep your existing structure the way it is.

If I put my downloads folder in my local folder won't rclone just move the files as they download?

Am I just supposed to put the completed downloads folder in the local folder?

I am clearly missing something. Could I just put my mergerfs folder in /home/server/data ?

Or are you just saying everything should be within the directories that are combined with mergerfs?

so..

mergerfs merging the local and cloud directories:

/home/server/data/local/downloads
/home/server/data/local/files-to-move

/home/server/data/cloud

I think this is solved, I haven't tested it yet but it seems like sticking my download folder in my local folder should do it.

Thanks for the help everyone.
ps I did have to edit my script a little to avoid moving and deleting files as they download

Normally I have my downloaders download direct into /home/server/data/local/downloads instead of going through mergerfs.

I set my cloud remote to NoCreate and I don't have a downloads folder on the remote, it doesn't upload my downloads folder. Files imported by sonarr will be moved to the media folder (appear as mergerfs/media, but real location is local/media). You can then use a script to run rclone move local/media myremote:/media with a cron job.

So I moved my downloads folder in my local folder so it's:

home/server/data/local/
-Shows
-Movies
-downloads

but it still takes awhile for sonarr and radarr to import the file and I can actually see the files grow in the shows and movies folders

what did I miss?

Also I do have my downloads going directly to ~/local/downloads

I ended up going back to v2 of sonarr and radarr and everything works fine now ???

If the goal is to use mergerfs, everything should go through with the exception of the upload to the cloud as that has to be off the local disk.

I think data is your mounted drive and cloud is the rclone and the mergerfs is home/server/mergerfs so everything should point to:

I break mine up into the apps so if I translate to your mount, I'd have:

home/server/mergerfs/NZB which has home/server/mergerfs/NZB/incomplete and home/server/mergerfs/completed
and I have a torrent area on
home/server/mergerfs/seed
TV and Movies are at
home/server/mergerfs/TV
home/server/mergerfs/Movies

Sonarr and Radarr move everything from the NZB and seed area to TV/Movies.

The only exception is my rclone move script which moves from the "data" local disk and I specifically exclude NZB and seed as exceptions.

You'd test hard linking by just doing

ls home/server/mergerfs/TV/test1 home/server/mergerfs/TV/test2 or something like that and if it works. You need to validate hard linking is on in Sonarr and Radarr. If those take a long time, you'd want to trace on the app and see if it's hard linking or not.

I believe there was a problem with my Sonarr and Radarr setup which were both v3.
It could've been several things such as permission issues, corrupted files, bad install, etc.

I removed both the Sonarr and Radarr v3 version and reverted back to v3 of both. Everything works fine now (under v2) which I can live with.

Thanks again for the help.

Just to confirm the issue was with Sonarr and Radarr v3 not hard linking.

I've been on V3 for Sonarr forever so I can't imagine that would be a problem. I'm only on V2 for Radarr so I can't comment on that.

Okay turns out I'm still having the issue. It is clearly an issue with hard linking that I just can't figure out. Here is some more info after moving stuff around trying to fix it:

BuyVM 512mb server with 256gb drive mounted to /home/server/data with fstab by UUID

df output:

Filesystem Size Used Avail Use% Mounted on
udev 227M 0 227M 0% /dev
tmpfs 48M 648K 48M 2% /run
/dev/vda1 9.3G 5.9G 3.0G 67% /
tmpfs 239M 8.0K 239M 1% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 239M 0 239M 0% /sys/fs/cgroup
/dev/sda1 252G 142G 98G 60% /home/server/data
gcrypt: 1.0P 0 1.0P 0% /home/server/data/cloud
local:cloud 1.1P 142G 1.1P 1% /home/server/data/mergerfs
tmpfs 48M 0 48M 0% /run/user/1000

rclone.service:

[Unit]
Description=RClone Service
Wants=network-online.target
After=network-online.target

[Service]
Type=notify
Environment=RCLONE_CONFIG=/home/server/.config/rclone/rclone.conf
KillMode=none
RestartSec=5
ExecStart=/usr/bin/rclone mount gcrypt: /home/server/data/cloud
--cache-dir /home/server/data/cache
--allow-other
--log-level INFO
--log-file /home/server/rclone.log
--poll-interval 15s
--umask 002
--allow-non-empty
--vfs-read-chunk-size 32M
ExecStop=/bin/fusermount -uz home/server/data/cloud
Restart=on-failure
User=server
Group=server

[Install]
WantedBy=multi-user.target

mergerfs.service:

[Unit]
Description=gmedia mergerfs mount
Requires=rclone.service
After=rclone.service

[Service]
Type=forking
ExecStart=/usr/bin/mergerfs /home/server/data/local:/home/server/data/cloud /home/server/data/mergerfs -o rw,use_ino,allow_other,func.getattr=newest,category.action=all,category.create=ff
KillMode=process
Restart=on-failure

[Install]
WantedBy=multi-user.target

tree of home:
.
├── data
│ ├── cache
│ ├── cloud (WHERE RCLONE MOUNTS)
│ ├── downloads
│ │ └── incomplete
│ ├── local
│ │ └── downloads (WHERE STUFF DOWNLOADS)
│ │ ├── complete
│ │ │ ├── Movies
│ │ │ └── tv
│ │ ├── incomplete
│ │ ├── nzb
│ │ ├── queue
│ │ └── tmp
│ ├── lost+found
│ └── mergerfs
└── Downloads
└── incomplete