Vfs cache failed to transfer file from cache to remote permission denied

What is the problem you are having with rclone?

I'm experiencing a very odd behavior on upload new subtitles ( as far as I can tel, only .srt files ) from bazarr, I have a very large library, bazarr started to replace a few subtitles a few days ago, the files go to cache and then the error appears on the log:
'''
2020/11/17 22:27:24 DEBUG : TV/11.22.63/Season 01/11.22.63.S01E03.HDTV.x264-LOL[rarbg].pt-BR.srt: vfs cache: starting upload
2020/11/17 22:27:24 ERROR : TV/11.22.63/Season 01/11.22.63.S01E03.HDTV.x264-LOL[rarbg].pt-BR.srt: Failed to copy: permission denied
2020/11/17 22:27:24 ERROR : TV/11.22.63/Season 01/11.22.63.S01E03.HDTV.x264-LOL[rarbg].pt-BR.srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
'''
at first I believed that it was a problem with permission on the mount, all the services are running on the system account, I even added -o flag with permission to everyone and the error persist, and oddly enough, sonarr and radarr are running the same as bazarr and they show no errors on uploading their files to the union remote.
I've tried with the latest rclone stable and also the latest beta, the error is the same.
a couple of days ago I had a few problems with "error 403 download quota for this files was exceed" and it was because of an error on bazarr setup and my mount settings, so I've stopped bazarr service for a few days, after I've got that problem sorted, I've started bazarr again and this problem surfaced.
I am able to write files to the union mount normally, series and movies are uploading just fine...
everything seams to be fine, except with the subtitles :frowning:
my basic setup is a union mount of Google and a local foder,all the apps are using the mount as path ( plex, sonarr, radar and etc ) and I use a script to upload from the local folder to google off normal use hours...

thanks for any assitance :wink:

What is your rclone version (output from rclone version)

rclone v1.53.2

  • os/arch: windows/amd64
  • go version: go1.15.2

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

Windows 10, X64 , version 2004

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

Google Drive, not shared drive or team drive, not sure if it matters...

The command you were trying to run (eg rclone copy /tmp remote:tmp)

mount UNION: U: --log-level INFO --volname "UNION MOUNT" --no-checksum --no-modtime --cache-dir C:\Cache --dir-cache-time 72h --drive-chunk-size 64M --vfs-read-chunk-size 32M --vfs-read-chunk-size-limit 512M --buffer-size 100M --rc --rc-user=xxx --rc-pass=xxx --rc-addr=10.0.0.20:5572 --rc-serve --rc-web-gui --fast-list --log-file C:\rclone\RClone_Union.txt --config "C:\Users\Jethro\.config\rclone\rclone.conf" --vfs-cache-mode writes -o --UserName=EVERYONE

The rclone config contents with secrets removed.

[JETHRO]
type = drive
client_id = my own API ID
client_secret = my secret
scope = drive
token = my token
root_folder_id = 

[UNION]
type = union
remotes = JETHRO:Media C:\Media
action_policy = epall

A log from the command with the -vv flag

Full Log at https://pastebin.com/YFWuRJuk

2020/11/17 23:20:30 DEBUG : TV/GLOW/Season 2/GLOW - S02E07 - Nothing Shattered.en.srt: vfs cache: checking remote fingerprint "33603,2020-06-18 22:43:15.86 +0000 UTC,2dc99853d79ef3ad23b0f976b187e2f9" against cached fingerprint "33603,2020-06-18 22:43:15.86 +0000 UTC,2dc99853d79ef3ad23b0f976b187e2f9"
2020/11/17 23:20:30 DEBUG : TV/GLOW/Season 2/GLOW - S02E07 - Nothing Shattered.en.srt: vfs cache: truncate to size=30776
2020/11/17 23:20:30 DEBUG : vfs cache: looking for range={Pos:0 Size:30776} in [{Pos:0 Size:30776}] - present true
2020/11/17 23:20:30 DEBUG : TV/GLOW/Season 2/GLOW - S02E07 - Nothing Shattered.en.srt: vfs cache: setting modification time to 2020-11-17 20:29:15.2530813 -0300 -03
2020/11/17 23:20:30 INFO  : TV/GLOW/Season 2/GLOW - S02E07 - Nothing Shattered.en.srt: vfs cache: queuing for upload in 5s
2020/11/17 23:20:30 DEBUG : TV/GLOW/Season 2: Added virtual directory entry vAdd: "GLOW - S02E07 - Nothing Shattered.en.srt"
2020/11/17 23:20:30 DEBUG : TV/GLOW/Season 1/GLOW - S01E03 - The Wrath of Kuntar.en.srt: vfs cache: starting upload
2020/11/17 23:20:30 ERROR : TV/GLOW/Season 1/GLOW - S01E03 - The Wrath of Kuntar.en.srt: Failed to copy: permission denied
2020/11/17 23:20:30 ERROR : TV/GLOW/Season 1/GLOW - S01E03 - The Wrath of Kuntar.en.srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E08 - The Good Twin.en.srt: vfs cache: checking remote fingerprint "35655,2020-06-18 22:43:44.275 +0000 UTC,11994028e89f945745f0c2cddcef167a" against cached fingerprint "35655,2020-06-18 22:43:44.275 +0000 UTC,11994028e89f945745f0c2cddcef167a"
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E08 - The Good Twin.en.srt: vfs cache: truncate to size=27357
2020/11/17 23:20:31 DEBUG : vfs cache: looking for range={Pos:0 Size:27357} in [{Pos:0 Size:27357}] - present true
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E08 - The Good Twin.en.srt: vfs cache: setting modification time to 2020-11-17 20:29:35.7169414 -0300 -03
2020/11/17 23:20:31 INFO  : TV/GLOW/Season 2/GLOW - S02E08 - The Good Twin.en.srt: vfs cache: queuing for upload in 5s
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2: Added virtual directory entry vAdd: "GLOW - S02E08 - The Good Twin.en.srt"
2020/11/17 23:20:31 DEBUG : rc: "core/stats": with parameters map[]
2020/11/17 23:20:31 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:14.4264007 errors:5 fatalError:false lastError:permission denied renames:0 retryError:true speed:0 transferTime:0.0049768 transfers:0]: <nil>
2020/11/17 23:20:31 DEBUG : rc: "core/stats": with parameters map[]
2020/11/17 23:20:31 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:14.4283832 errors:5 fatalError:false lastError:permission denied renames:0 retryError:true speed:0 transferTime:0.0049768 transfers:0]: <nil>
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E09 - Rosalie.en.srt: vfs cache: checking remote fingerprint "45283,2020-06-18 22:44:15.735 +0000 UTC,d769f0f0fcde62554fc8fab4626b2b68" against cached fingerprint "45283,2020-06-18 22:44:15.735 +0000 UTC,d769f0f0fcde62554fc8fab4626b2b68"
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E09 - Rosalie.en.srt: vfs cache: truncate to size=40879
2020/11/17 23:20:31 DEBUG : vfs cache: looking for range={Pos:0 Size:40879} in [{Pos:0 Size:40879}] - present true
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E09 - Rosalie.en.srt: vfs cache: setting modification time to 2020-11-17 20:30:00.2621949 -0300 -03
2020/11/17 23:20:31 INFO  : TV/GLOW/Season 2/GLOW - S02E09 - Rosalie.en.srt: vfs cache: queuing for upload in 5s
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2: Added virtual directory entry vAdd: "GLOW - S02E09 - Rosalie.en.srt"
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 1/GLOW - S01E04 - The Dusty Spur.en.srt: vfs cache: starting upload
2020/11/17 23:20:31 ERROR : TV/GLOW/Season 1/GLOW - S01E04 - The Dusty Spur.en.srt: Failed to copy: permission denied
2020/11/17 23:20:31 ERROR : TV/GLOW/Season 1/GLOW - S01E04 - The Dusty Spur.en.srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E10 - Every Potato Has a Receipt.en.srt: vfs cache: checking remote fingerprint "54346,2020-06-18 22:48:13.582 +0000 UTC,f51a0b0bf0c3188d02405ba7c3e83201" against cached fingerprint "54346,2020-06-18 22:48:13.582 +0000 UTC,f51a0b0bf0c3188d02405ba7c3e83201"
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E10 - Every Potato Has a Receipt.en.srt: vfs cache: truncate to size=47944
2020/11/17 23:20:31 DEBUG : vfs cache: looking for range={Pos:0 Size:47944} in [{Pos:0 Size:47944}] - present true
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2/GLOW - S02E10 - Every Potato Has a Receipt.en.srt: vfs cache: setting modification time to 2020-11-17 20:30:25.3510411 -0300 -03
2020/11/17 23:20:31 INFO  : TV/GLOW/Season 2/GLOW - S02E10 - Every Potato Has a Receipt.en.srt: vfs cache: queuing for upload in 5s
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 2: Added virtual directory entry vAdd: "GLOW - S02E10 - Every Potato Has a Receipt.en.srt"
2020/11/17 23:20:31 DEBUG : TV/GLOW/Season 1/GLOW - S01E05 - Debbie Does Something.en.srt: vfs cache: starting upload
2020/11/17 23:20:31 ERROR : TV/GLOW/Season 1/GLOW - S01E05 - Debbie Does Something.en.srt: Failed to copy: permission denied
2020/11/17 23:20:31 ERROR : TV/GLOW/Season 1/GLOW - S01E05 - Debbie Does Something.en.srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
2020/11/17 23:20:32 DEBUG : TV/GLOW/Season 3/GLOW - S03E01 - Up, Up, Up.en.srt: vfs cache: checking remote fingerprint "48712,2019-08-10 12:43:47.326 +0000 UTC,47533d3589127616c2d9260cc30de82b" against cached fingerprint "48712,2019-08-10 12:43:47.326 +0000 UTC,47533d3589127616c2d9260cc30de82b"
2020/11/17 23:20:32 DEBUG : TV/GLOW/Season 3/GLOW - S03E01 - Up, Up, Up.en.srt: vfs cache: truncate to size=42893
2020/11/17 23:20:32 DEBUG : rc: "core/stats": with parameters map[]
2020/11/17 23:20:32 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:15.4275684 errors:7 fatalError:false lastError:permission denied renames:0 retryError:true speed:0 transferTime:0.0049768 transfers:0]: <nil>
2020/11/17 23:20:32 DEBUG : rc: "core/stats": with parameters map[]
2020/11/17 23:20:32 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:15.4285739 errors:7 fatalError:false lastError:permission denied renames:0 retryError:true speed:0 transferTime:0.0049768 transfers:0]: <nil>
2020/11/17 23:20:32 DEBUG : vfs cache: looking for range={Pos:0 Size:42893} in [{Pos:0 Size:42893}] - present true
2020/11/17 23:20:32 DEBUG : TV/GLOW/Season 3/GLOW - S03E01 - Up, Up, Up.en.srt: vfs cache: setting modification time to 2020-11-17 20:30:48.9330285 -0300 -03
2020/11/17 23:20:32 INFO  : TV/GLOW/Season 3/GLOW - S03E01 - Up, Up, Up.en.srt: vfs cache: queuing for upload in 5s
2020/11/17 23:20:32 DEBUG : TV/GLOW/Season 3: Added virtual directory entry vAdd: "GLOW - S03E01 - Up, Up, Up.en.srt"
2020/11/17 23:20:32 DEBUG : TV/GLOW/Season 1/GLOW - S01E06 - This Is One of Those Moments.en.srt: vfs cache: starting upload
2020/11/17 23:20:32 ERROR : TV/GLOW/Season 1/GLOW - S01E06 - This Is One of Those Moments.en.srt: Failed to copy: permission denied
2020/11/17 23:20:32 ERROR : TV/GLOW/Season 1/GLOW - S01E06 - This Is One of Those Moments.en.srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
2020/11/17 23:20:32 DEBUG : rc: "core/stats": with parameters map[]

I've just tested an manual upload using this command to move from cache to the remote:
'''
"C:\RClone\rclone.exe" move "C:\Cache\vfs\UNION\TV" "JETHRO:Media\TV" --progress --stats-one-line --fast-list --log-file="C:\rclone\RCLONE_MOVE_TV_JOB_%date:/=_%.log" -vv
'''
it worked as it was supposed to, all the *.srt files were upload to the remote...

Well... Now it got really interesting... or, as we say here in Brazil, suck on this mango !
I've created a new remote, just for bazarr, with the same settings as the original remote,
and also I've created new credentials on Google API Console for this new bazarr remote.

here is the new rclone config:
'''
[JETHRO]
type = drive
client_id =
client_secret =
scope = drive
token =
root_folder_id =

[UNION]
type = union
remotes = JETHRO:Media C:\Media
action_policy = epall

[BAZARR_UNION]
type = union
upstreams = BAZARR:Media C:\Bazarr_Union

[BAZARR]
type = drive
client_id =
client_secret =
scope = drive
token =
'''

command line for the bazarr mount
'''
mount BAZARR_UNION: V: --log-level INFO --no-checksum --no-modtime --cache-dir C:\Bazarr_cache --dir-cache-time 48h --drive-chunk-size 64M --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 2G --vfs-cache-mode writes --buffer-size 256M --poll-interval 15s --fast-list --volname "BAZARR UNION MOUNT" --log-file C:\rclone\RClone_Bazarr_Union.txt --config "C:\Users\Jethro.config\rclone\rclone.conf" -o --UserName=EVERYONE
'''

command line for the original remote ( edited from the original post just to make easier )
'''
mount UNION: U: --log-level INFO --no-checksum --no-modtime --cache-dir C:\Cache --dir-cache-time 48h --drive-chunk-size 64M --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 2G --vfs-cache-mode writes --buffer-size 256M --poll-interval 15s --fast-list --volname "UNION MOUNT" --log-file C:\rclone\RClone_Union.txt --config "C:\Users\Jethro.config\rclone\rclone.conf" -o --UserName=EVERYONE
'''

Edited an subtitle on bazarr app on the original remote, and as expected, the upload error is logged:
'''
2020/11/19 00:56:59 INFO : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].pt-BR.srt: vfs cache: queuing for upload in 5s
2020/11/19 00:57:05 ERROR : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].pt-BR.srt: Failed to copy: permission denied
2020/11/19 00:57:05 ERROR : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].pt-BR.srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
'''

Changed bazarr app to use the new remote, and edited the same subtitle and BUM ! It worked normally:
'''
2020/11/19 01:03:44 INFO : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].pt-BR.srt: vfs cache: queuing for upload in 5s
2020/11/19 01:04:00 NOTICE: Free Space is not supported for upstream BAZARR, treating as infinite
2020/11/19 01:04:04 INFO : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].pt-BR.srt: Copied (new)
2020/11/19 01:04:04 INFO : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].pt-BR.srt: vfs cache: upload succeeded try #1
'''

I've double checked the folders on the local disk, NTFS permissions are identical
now I have no clue what to try next...

The only thing that comes to mind is permissions problems in the VFS cache directory itself. Can you check that out in C:\Cache?

Thanks for the input Nick,
But I've checked the permission... They are exactly the same on both folders...
I even created a new folder with the same permission, the same error...
I've deleted the C:\cache folder and created again , set the permissions and the error is the same...

'''
C:\Users\Jethro>icacls c:\Cache
c:\Cache NT AUTHORITY\Authenticated Users:(OI)(CI)(F)
Everyone:(OI)(CI)(F)
BUILTIN\Users:(OI)(CI)(F)
BUILTIN\Administrators:(I)(OI)(CI)(F)
NT AUTHORITY\SYSTEM:(I)(OI)(CI)(F)
BUILTIN\Users:(I)(OI)(CI)(RX)
NT AUTHORITY\Authenticated Users:(I)(M)
NT AUTHORITY\Authenticated Users:(I)(OI)(CI)(IO)(M)

Successfully processed 1 files; Failed processing 0 files

C:\Users\Jethro>icacls c:\bazarr_Cache
c:\bazarr_Cache NT AUTHORITY\Authenticated Users:(OI)(CI)(F)
Everyone:(OI)(CI)(F)
BUILTIN\Users:(OI)(CI)(F)
BUILTIN\Administrators:(I)(OI)(CI)(F)
NT AUTHORITY\SYSTEM:(I)(OI)(CI)(F)
BUILTIN\Users:(I)(OI)(CI)(RX)
NT AUTHORITY\Authenticated Users:(I)(M)
NT AUTHORITY\Authenticated Users:(I)(OI)(CI)(IO)(M)

Successfully processed 1 files; Failed processing 0 files
'''

I've also created new credentials on the Google API Console for the original remote, same problem...

That "permission denied" error is most likely a local file system error.

So if it isn't the C:\Cache directory, could it be the C:\Media directory which is part of your union?

Well, now I believe you are on to something...
the file is on the C:\Cache folder, as expected.
and not on the C:\Media folder, with is the folder writable by the union mount.
I've created a new local folder for the union and set the permission according, same error...
during this processes , I've tried to copy the .srt in question from the C:\Cache folder to U:\Movies\FHD\Assault on Wall Street (2013) And I've got an error ! I cannot replace a file on that folder, in fact, I cannot do anything in this specific folder...

I'm working on the assumption that the flag I use on the mount "-o --UserName=EVERYONE" will set full control on the mount for all folders and files, but now I'm starting to believe that there is an issue here... I'll do more testing and report back.

again, thanks for the input on this issue Nick.

1 Like

hi,

-o --UserName=EVERYONE

in windows, everyone is a group, not a user.
in this snippet, i added the group everyone to the permissions.
if you look closely at the icons, you can see the difference between a user and a group

image

if you run rclone as system user, then all processs can see it.

another option is to mount to a folder, not a drive letter, which is what i do.
you might find that works around some windows permissions problems.
rclone.exe mount wasabicrypt01: b:\mount\rclone\wasabicrypt01

Thanks for the tip,
I do mount using the system account, using NSSM to install and manage the service.
I will test as a folder mount, but I don't like this as a solution... this is a production environment :wink:
i don't like to have to change the paths for plex, sonarr, radarr and etc...

not sure what you mean about production environment and using a folder mount?

Sorry, I mean that this is an already setup and in use server... To have to change the root path on plex and all other applications I think it will be allot of work... All of then are using U:\Movies or U:\Series...
I will test the folder mount that you mention to test if the same problem still remain.
although, I already have another mount ( for bazarr ) with the same settings and not the same problem...

Just tested the folder mount with basically the same command line:
'''
rclone.exe mount UNION: C:\Mount --log-level INFO --stats-log-level NOTICE --no-checksum --no-modtime --attr-timeout 1000h --cache-dir C:\Cache --dir-cache-time 1000h --drive-chunk-size 64M --vfs-read-chunk-size 64M --vfs-read-chunk-size-limit 2G --vfs-cache-mode writes --buffer-size 256M --fast-list --rc --rc-user=xxx --rc-pass=xxx --rc-addr=10.0.0.20:5574 --rc-serve --rc-enable-metrics --rc-web-gui --rc-web-gui-update --log-file C:\rclone\RClone_Union_folder.txt --config "C:\Users\Jethro.config\rclone\rclone.conf" -o --UserName=EVERYONE
'''

Same error...

'''
2020/11/20 14:13:02 INFO : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].srt: vfs cache: queuing for upload in 5s
2020/11/20 14:13:07 ERROR : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].srt: Failed to copy: permission denied
2020/11/20 14:13:07 ERROR : Movies/FHD/Assault on Wall Street (2013)/Assault on Wall Street (2013) [1080p].srt: vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: permission denied
'''

what is really bugging me is that the bazarr mount, on V: does not show the same problem...

'''
rclone.exe mount BAZARR_UNION: V: --log-level INFO --stats-log-level NOTICE --no-checksum --no-modtime --cache-dir C:\Bazarr_cache --dir-cache-time 48h --drive-chunk-size 64M --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 2G --vfs-cache-mode writes --buffer-size 256M --poll-interval 15s --fast-list --volname "BAZARR UNION MOUNT" --rc --rc-user=xxx --rc-pass=xxx --rc-addr=10.0.0.20:5573 --rc-serve --rc-enable-metrics --rc-web-gui --rc-web-gui-update --log-file C:\rclone\RClone_Bazarr_Union.txt --config "C:\Users\Jethro.config\rclone\rclone.conf" -o --UserName=EVERYONE
'''

--fast-list does does nothing on a mount