RClone not syncing new files immediately with S3 and worker failures

Help and Support
1

Hello all,

I have rclone integrated into my project which contains server which is responsible to upload files into s3, and worker machines which access that s3 bucket via rclone mounted directory.
I have an issue with rclone where when a new file is uploaded into S3, it's not immediately synced into the mounted dirs on worker machines, causing failures. After a failure, rclone successfully syncs the file during the next try. Is there a way to make rclone stop or hang the file metadata read operation before it syncs the file, or any other recommended solution for this problem?

This is my config:

[Service]
Type=notify
ExecStart=/usr/bin/rclone mount \\
    --cache-dir="${CACHE_DIR}" \\
    --vfs-cache-mode full \\
    --vfs-cache-max-age 5000h \\
    --vfs-cache-max-size 100G \\
    --no-modtime \\
    --read-only \\
    --fast-list \\
    --checksum \\
    --allow-other \\
    "${REMOTE_NAME}":"${BUCKET_NAME}" "${MOUNT_DIR}"
ExecStop=/bin/fusermount -uz "${MOUNT_DIR}"
Restart=on-failure
KillMode=none
RestartSec=1600
User=${USER}
Group=$(id -gn "${USER}")

Any suggestions or guidance would be greatly appreciated. Thank you!

2

debug logfile will allow to have a look at the nature of these failures.

Also content of your rclone.config might be hiding some clues.

3

config:

[StorageS3]
type = s3
access_key_id = xxxxxxxxxxxxxxxxxxxxxxx
secret_access_key = xxxxxxxxxxxxxxxxxxxxxxx
acl = private
endpoint = https://s3.xx.io.xx.xx.net
v4_auth = true
region = par
provider = Other
env_auth = false
location_constraint = 
storage_class = STANDARD
4

This is log getting when accessing newly uploaded file qr.zip:
pastebin: 2023/05/31 08:22:12 DEBUG : /: Attr: 2023/05/31 08:22:12 DEBUG : /: >Attr: att - Pastebin.com

2023/05/31 08:22:12 DEBUG : /: Attr: 
2023/05/31 08:22:12 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/05/31 08:22:19 DEBUG : /: Lookup: name="files"
2023/05/31 08:22:19 DEBUG : /: >Lookup: node=files/, err=<nil>
2023/05/31 08:22:19 DEBUG : files/: Attr: 
2023/05/31 08:22:19 DEBUG : files/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/05/31 08:22:19 DEBUG : files/: Lookup: name="qr.zip"
2023/05/31 08:22:19 DEBUG : files/: >Lookup: node=files/qr.zip, err=<nil>
2023/05/31 08:22:19 DEBUG : files/qr.zip: Attr: 
2023/05/31 08:22:19 DEBUG : files/qr.zip: >Attr: a=valid=1s ino=0 size=2311483 mode=-rw-r--r--, err=<nil>
2023/05/31 08:22:19 DEBUG : files/qr.zip: Open: flags=OpenReadOnly+OpenNonblock
2023/05/31 08:22:19 DEBUG : files/qr.zip: Open: flags=O_RDONLY|0x800
2023/05/31 08:22:19 DEBUG : files/qr.zip: newRWFileHandle: 
2023/05/31 08:22:19 DEBUG : files/qr.zip: >newRWFileHandle: err=<nil>
2023/05/31 08:22:19 DEBUG : files/qr.zip: >Open: fd=files/qr.zip (rw), err=<nil>
2023/05/31 08:22:19 DEBUG : files/qr.zip: >Open: fh=&{files/qr.zip (rw)}, err=<nil>
2023/05/31 08:22:19 DEBUG : &{files/qr.zip (rw)}: Read: len=131072, offset=0
2023/05/31 08:22:19 DEBUG : files/qr.zip(0xc00141e000): _readAt: size=131072, off=0
2023/05/31 08:22:19 DEBUG : files/qr.zip(0xc00141e000): openPending: 
2023/05/31 08:22:19 NOTICE: files/qr.zip: Failed to read metadata: Forbidden: Forbidden
	status code: 403, request id: tx23f1f1ae22f24c07bf39a-00647703bb, host id: tx23f1f1ae22f24c07bf39a-00647703bb
2023/05/31 08:22:19 DEBUG : files/qr.zip: vfs cache: checking remote fingerprint "2311483,2023-05-31 08:22:19.926659844 +0000 UTC,cb55da2455bd5e8e47aac856ada7a56c" against cached fingerprint ""
2023/05/31 08:22:19 DEBUG : files/qr.zip: vfs cache: truncate to size=2311483
2023/05/31 08:22:19 DEBUG : files: Added virtual directory entry vAddFile: "qr.zip"
2023/05/31 08:22:19 DEBUG : files/qr.zip(0xc00141e000): >openPending: err=<nil>
2023/05/31 08:22:19 DEBUG : vfs cache: looking for range={Pos:0 Size:131072} in [] - present false
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:19 INFO  : files/qr.zip: vfs cache: downloader: error count now 1: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx979b02488cc445768003e-00647703bb, host id: tx979b02488cc445768003e-00647703bb
2023/05/31 08:22:19 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx979b02488cc445768003e-00647703bb, host id: tx979b02488cc445768003e-00647703bb
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:19 INFO  : files/qr.zip: vfs cache: downloader: error count now 2: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx1ea66c99c28d4165bf593-00647703bb, host id: tx1ea66c99c28d4165bf593-00647703bb
2023/05/31 08:22:19 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx1ea66c99c28d4165bf593-00647703bb, host id: tx1ea66c99c28d4165bf593-00647703bb
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:19 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 3: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx8e5999f6d5a643259da4c-00647703bb, host id: tx8e5999f6d5a643259da4c-00647703bb
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx8e5999f6d5a643259da4c-00647703bb, host id: tx8e5999f6d5a643259da4c-00647703bb
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 4: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx0272330d1c7d4c6a992d0-00647703bc, host id: tx0272330d1c7d4c6a992d0-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx0272330d1c7d4c6a992d0-00647703bc, host id: tx0272330d1c7d4c6a992d0-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 5: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx4df1e4fd06514a14a1d4d-00647703bc, host id: tx4df1e4fd06514a14a1d4d-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx4df1e4fd06514a14a1d4d-00647703bc, host id: tx4df1e4fd06514a14a1d4d-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 6: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx922cb349e0ea428ca04e0-00647703bc, host id: tx922cb349e0ea428ca04e0-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx922cb349e0ea428ca04e0-00647703bc, host id: tx922cb349e0ea428ca04e0-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 7: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx52e1e401665f478085ff4-00647703bc, host id: tx52e1e401665f478085ff4-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx52e1e401665f478085ff4-00647703bc, host id: tx52e1e401665f478085ff4-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 8: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txd736144513954b96b6874-00647703bc, host id: txd736144513954b96b6874-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txd736144513954b96b6874-00647703bc, host id: txd736144513954b96b6874-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 9: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx2029a3d7bbe24699bfc28-00647703bc, host id: tx2029a3d7bbe24699bfc28-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx2029a3d7bbe24699bfc28-00647703bc, host id: tx2029a3d7bbe24699bfc28-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 10: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx7471221dc4a74afe93702-00647703bc, host id: tx7471221dc4a74afe93702-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: tx7471221dc4a74afe93702-00647703bc, host id: tx7471221dc4a74afe93702-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 11: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: too many errors 11/10: last error: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to kick waiters: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to _ensure cache vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: vfs cache: failed to _ensure cache vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc is not out of space
2023/05/31 08:22:20 DEBUG : files/qr.zip(0xc00141e000): >_readAt: n=0, err=vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 ERROR : IO error: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 DEBUG : &{files/qr.zip (rw)}: >Read: read=0, err=vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txe3d044d07d4e479bb45ce-00647703bc, host id: txe3d044d07d4e479bb45ce-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 DEBUG : &{files/qr.zip (rw)}: Read: len=4096, offset=0
2023/05/31 08:22:20 DEBUG : files/qr.zip(0xc00141e000): _readAt: size=4096, off=0
2023/05/31 08:22:20 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 12: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: too many errors 12/10: last error: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to kick waiters: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to _ensure cache vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: vfs cache: failed to _ensure cache vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc is not out of space
2023/05/31 08:22:20 DEBUG : files/qr.zip(0xc00141e000): >_readAt: n=0, err=vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 ERROR : IO error: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
2023/05/31 08:22:20 DEBUG : files/qr.zip: ChunkedReader.openRange at 0 length 134217728
2023/05/31 08:22:20 DEBUG : &{files/qr.zip (rw)}: >Read: read=0, err=vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txf84cd871d45d4503b3b7b-00647703bc, host id: txf84cd871d45d4503b3b7b-00647703bc
2023/05/31 08:22:20 DEBUG : &{files/qr.zip (rw)}: Flush: 
2023/05/31 08:22:20 DEBUG : files/qr.zip(0xc00141e000): RWFileHandle.Flush
2023/05/31 08:22:20 DEBUG : &{files/qr.zip (rw)}: >Flush: err=<nil>
2023/05/31 08:22:20 DEBUG : &{files/qr.zip (rw)}: Release: 
2023/05/31 08:22:20 DEBUG : files/qr.zip(0xc00141e000): RWFileHandle.Release
2023/05/31 08:22:20 DEBUG : files/qr.zip(0xc00141e000): close: 
2023/05/31 08:22:20 INFO  : files/qr.zip: vfs cache: downloader: error count now 13: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txa8485f95129f4d7f9a532-00647703bc, host id: txa8485f95129f4d7f9a532-00647703bc
2023/05/31 08:22:20 ERROR : files/qr.zip: vfs cache: failed to download: vfs reader: failed to write to cache file: AccessDenied: Access Denied.
	status code: 403, request id: txa8485f95129f4d7f9a532-00647703bc, host id: txa8485f95129f4d7f9a532-00647703bc
2023/05/31 08:22:20 NOTICE: files/qr.zip: Failed to read metadata: Forbidden: Forbidden
	status code: 403, request id: tx6b0ab889aa6447a9a93e7-00647703bc, host id: tx6b0ab889aa6447a9a93e7-00647703bc
2023/05/31 08:22:20 DEBUG : files/qr.zip: vfs cache: setting modification time to 2023-05-31 08:22:20.257351853 +0000 UTC m=+387.654224310
5

This appears to be the problem, or one of them .

Rclone is trying to HEAD this object and it needs permissions to do so.

6

API access key && secret key used has full persmisson on the S3 storage, it's OVH's S3 storage btw
I removed --read-only flag and able to delete files, so creds/connection good

What can be reason for that?

7

I know nothing about OVH S3 but with AWS:

you could get this error 403 Forbidden for HEAD if user does not have the s3:ListBucket permission

8

You can also try this:

no-head-object = true

in your config. But I am not sure how it will work with mount.

9

hi, about the status code: 403.

can you reproduce the issue on a single file without using rclone mount, something like
rclone copy /files/qr.zip remote:bucket --dry-run dump=headers

since i always use a locked down iam/bucket policies, i need to use --s3-no-check-bucket

10

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