Cache error - "failed to rename queued file for upload"

#1

Like many others, I’ve been using a Cache-Crypt mount to GSuite to host my media for Plex. I Also run Sonarr and Radarr to download directly into the cache mount so that files are immediately available to Plex. I have not been using the --cache-tmp-upload-path so everything is written to the cache, but I am seeing the odd error message in the log saying “chunk not found” when Sonarr/Radarr are processing downloads and writing them to the mount. I’ve cleared the cache (both with KILL and using the --cache-db-purge switch on the Rclone mount command) but it still occasionally occurs. It doesn’t affect anything, and the files end up in the right place with the right names.

So I thought I’d try using the --cache-tmp-upload-path to see if it helped eliminate the error – but this morning I still saw a couple of instances of it plus another about “failed to rename queued file for upload”. I know Sonarr/Radarr copy files from the download client and adds a .partial suffix, and then rename them to their proper name immediately – it’s this that seems to cause the error, and I’ve managed to reproduce it by using the ‘cp’ file immediately followed by ‘mv’ to rename it. It seems to happen on larger files – I’m testing it with a 4.7GB mkv.

My rclone.conf looks like this:

[Gsuite-Laurie]
type = drive
client_id = xxxxx
client_secret = xxxxx
scope = drive
root_folder_id =
service_account_file =
token = xxxxx

[Laurie-Gsuite-Cache]
type = cache
remote = Gsuite-Laurie:Laurie-Enc
chunk_size = 32M
info_age = 1d
plex_url = xxxxx
plex_username = xxxxx
plex_password = wxxxxx

[Laurie-Gsuite-Cache-Crypt]
type = crypt
remote = Laurie-Gsuite-Cache:
password = xxxxx
password2 = xxxxx

My mount command is

rclone mount Laurie-Gsuite-Cache-Crypt: /home19/renzz27/files/Laurie-Enc/ -c --dir-cache-time 60m0s --allow-other --drive-chunk-size=512M --vfs-cache-mode off --cache-tmp-upload-path=/home19/renzz27/.cache/Laurie-Plex/ --log-file=/home19/renzz27/rclone-mount-log.log -v &

I’m using v1.47

I have a file called originalfile.mkv which I’m copying into the mount to a name of copiedfile.mkv and then immediately renaming it to renamedfile.mkv . The command that does this is

cd ~/files/Laurie ; cp originalfile.mkv ~/files/Laurie-Enc/Recordings/copiedfile.mkv ; cd ~/files/Laurie-Enc/Recordings ; mv copiedfile.mkv renamedfile.mkv ; cd ~/files/Laurie

When I run it I see in the log the file being queued for upload, and when it ends I get the “failed to rename” error logged. At this point, the ‘mv’ command is hung and I can still see the file called copiedfile.mkv in the target folder. What seems to happen is the upload is then done again for the (locally) renamed file and eventually the mv command returns and everything is as it should be.

What I would expect to happen is the original file should be uploaded and then the mv command run to do a server side rename, but it seems the file is uploaded twice to achieve the rename.

I have yet to reproduce the “chunk not found” error but I have a feeling it’s tied in with this, which looks like a possible timing problem.

Here’s the log showing the events.

2019/05/13 14:56:09 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: put: uploaded in temp fs
2019/05/13 14:56:10 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: put: queued for upload
2019/05/13 14:56:10 INFO : ubkf5efce96ottub0hlfs5143c: put: cache expired
2019/05/13 14:56:25 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: background upload: started upload
2019/05/13 14:57:54 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: Copied (new)
2019/05/13 14:57:55 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: Deleted
2019/05/13 14:57:55 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: background upload: uploaded entry
2019/05/13 14:57:55 INFO : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: finished background upload
2019/05/13 14:57:55 ERROR : ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: failed to rename queued file for upload: pending upload (ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k) not found unexpected end of JSON input
2019/05/13 14:57:56 ERROR : worker-0 : object open failed 0: open /home19/renzz27/.cache/Laurie-Plex/ubkf5efce96ottub0hlfs5143c/ckmnlnen7sb564qfng23k9ho3k: no such file or directory
2019/05/13 14:58:47 INFO : Recordings/copiedfile.mkv: received cache expiry notification
2019/05/13 14:58:57 INFO : cache-cleanup: chunks 43, est. size: 1.328G
2019/05/13 15:00:57 INFO : cache-cleanup: chunks 14, est. size: 414.491M
2019/05/13 15:01:06 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: put: uploaded in temp fs
2019/05/13 15:01:06 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: put: queued for upload
2019/05/13 15:01:06 INFO : ubkf5efce96ottub0hlfs5143c: put: cache expired
2019/05/13 15:01:06 INFO : Recordings/copiedfile.mkv: Copied (new)
2019/05/13 15:01:08 INFO : Recordings/copiedfile.mkv: Deleted
2019/05/13 15:01:22 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: background upload: started upload
2019/05/13 15:01:47 INFO : Recordings/copiedfile.mkv: received cache expiry notification
2019/05/13 15:02:48 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: Copied (new)
2019/05/13 15:02:49 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: Deleted
2019/05/13 15:02:49 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: background upload: uploaded entry
2019/05/13 15:02:49 INFO : ubkf5efce96ottub0hlfs5143c/3o1ah5eq62ph2dpn0056p5rq7s: finished background upload
2019/05/13 15:03:47 INFO : Recordings/renamedfile.mkv: received cache expiry notification

Here's the log from this morning when Sonarr was downloading - the "chunk not found" error does seem tied up with the "failed to rename queued file for upload" error:

2019/05/13 08:37:21 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: put: uploaded in temp fs
2019/05/13 08:37:22 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: put: queued for upload
2019/05/13 08:37:29 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns: put: cache expired
2019/05/13 08:37:38 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: background upload: started upload
2019/05/13 08:38:47 INFO : Plex/TV/Killing Eve/Killing.Eve.S02E06.1080p.WEB.H264-METCON English.mkv.partial~: received cache expiry notification
2019/05/13 08:39:09 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: Copied (new)
2019/05/13 08:39:12 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: Deleted
2019/05/13 08:39:12 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: background upload: uploaded entry
2019/05/13 08:39:13 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: finished background upload
2019/05/13 08:39:13 ERROR : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: failed to rename queued file for upload: pending upload (quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g) not found unexpected end of JSON input
2019/05/13 08:39:22 INFO : cache-cleanup: chunks 5, est. size: 141.706M
2019/05/13 08:39:29 INFO : cache-cleanup: chunks 5, est. size: 141.706M
2019/05/13 08:40:03 ERROR : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: (1006632960/2366262800) error (chunk not found 1006632960) response
2019/05/13 08:40:25 INFO : cache-cleanup: chunks 30, est. size: 941.706M
2019/05/13 08:40:30 INFO : cache-cleanup: chunks 3, est. size: 77.706M
2019/05/13 08:41:25 INFO : cache-cleanup: chunks 27, est. size: 813.706M
2019/05/13 08:41:27 ERROR : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/2dni53ech6ud2gg16t4nmc0dojooci01vnqqv74fdf4et09keo0u2pbhiopfe448nk6qmis7u65uakrldqd5bp1t648pe780ksqqs4g: (2348810240/2366262800) error (chunk not found 2348810240) response
2019/05/13 08:41:29 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/638n2464khcl897a6180shi7habo9dbl1pevecq34vbv3cfrsin9kmkmfo23nehu3p61367erpq45u0n0a1hp19c51csjdnjk09bebo: put: uploaded in temp fs
2019/05/13 08:41:29 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/638n2464khcl897a6180shi7habo9dbl1pevecq34vbv3cfrsin9kmkmfo23nehu3p61367erpq45u0n0a1hp19c51csjdnjk09bebo: put: queued for upload
2019/05/13 08:41:30 INFO : cache-cleanup: chunks 2, est. size: 48.027M
2019/05/13 08:41:30 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns: put: cache expired
2019/05/13 08:41:30 INFO : Plex/TV/Killing Eve/Killing.Eve.S02E06.1080p.WEB.H264-METCON English.mkv.partial~: Copied (new)
2019/05/13 08:41:33 INFO : Plex/TV/Killing Eve/Killing.Eve.S02E06.1080p.WEB.H264-METCON English.mkv.partial~: Deleted
2019/05/13 08:41:45 INFO : quqnauva0ngvg55rat0887qobc/6vhcaf5rkgsdajj6r8d15kthok/nvu4uilgvo7pvfmc9dgnajhvns/638n2464khcl897a6180shi7habo9dbl1pevecq34vbv3cfrsin9kmkmfo23nehu3p61367erpq45u0n0a1hp19c51csjdnjk09bebo: background upload: started upload
2019/05/13 08:41:50 INFO : Plex/TV/Killing Eve/Killing.Eve.S02E06.1080p.WEB.H264-METCON English.mkv.partial~: received cache expiry notification
2

Thanks

#2

Can you put the mount in debug "-vv" and capture the error?

#3

So this is weird - I can't get it to do it with -vv. I tried several times, even with a larger 8GB file and it still seems to work ok (if I'm reading the log correctly). It looks like it does the rename before the upload of the copied file starts, which makes more sense. I wonder if it's a timing issue and running with full debug slows it down enough to work correctly?

Not sure what to do next but the debug log is at

in case it shows anything.

#4

Sonarr / Radarr do some funny things with the partial files going on. Many releases ago, I had trouble with that as well and just removed that from my process as I write locally first.

I also couldn't reproduce it every-time either. If you can get a debug log with an issue, we can probably get the problem identified.