S3 and intermittent 403 errors with file renames and drag and drop operations in Windows Explorer

jassenjj · December 14, 2022, 9:05am

What is the problem you are having with rclone?

I use rclone to mount S3 drives on windows machines. I experience intermittent issues with file renames and drag-and-drop operations from Windows Explorer on various machines and various Windows editions.

If I try to drag and drop a file from one folder to a subfolder very often (and with some files repeatedly) I get an I/O error message. The file is then present in both places and I have to delete the original file manually, which happens without an issue.

Not that often the issue happens with file rename operations. The problem becomes very apparent if I open a Word document and try to edit and save it as Word does a lot of temp file renames during the process.

From my analysis (speculation, could be very wrong) I figured out that if I run the rclone mount command with -vv flag the issue is "almost" not reproducible. It seems that the S3 server-side copy command takes some time to run on the server and the subsequent delete operation comes too early and it gets Access denied error 403. If extensive logging is enabled with the -vv flag, it slows down rclone enough so that the issue happens very rarely and I cannot replicate it on demand.

I played quite a lot with retries, and I also noticed that for the low-level retries there is no option for delay. All the low level retries of the delete command happen very fast and all of them get the 403 error, which is not present if I manually delete the initial file immediately after.

All of this makes the local folder structure and contents to differ from the server - many copies of the same file (with the same name!!!) appear in Windows explorer and some of them cannot be opened with a 404 not found error. This I usually fix by remounting the drive.

Run the command 'rclone version' and share the full output of the command.

Machine 1 - an Amazon Workspace machine:

rclone v1.60.1
- os/version: Microsoft Windows Server 2016 Datacenter 1607 (64 bit)
- os/kernel: 10.0.14393.5501 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.19.3
- go/linking: static
- go/tags: cmount

Machine 2 - my laptop:

rclone v1.60.1
- os/version: Microsoft Windows 11 Pro 22H2 (64 bit)
- os/kernel: 10.0.22621.819 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.19.3
- go/linking: static
- go/tags: cmount

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

S3

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

Operations from Windows explorer.
The drive is mounted with the following options using the SYSTEM account:

rclone.exe mount algos1storage1:algos1storage1/ Y: --vfs-cache-mode full -v --s3-no-check-bucket --vfs-fast-fingerprint --transfers 1 --retries 10 --retries-sleep 500ms --vfs-write-back 1s --volname "Algos Server" --log-file D:/rclone/rclone_y.log --file-perms 0777 --dir-perms 0777 -o --UserName=XXX

The rclone config contents with secrets removed.

[algos1storage1]
type = s3
provider = AWS
access_key_id = XXX
secret_access_key = XXX
region = eu-west-1

A log from the command with the `-vv` flag

Note: the 2 logs below come from -v flag only because the issue is hard to reproduce with the -vv flag. In the second log it is obvious how some rename operations go without an issue and then a drag and drop fails in the same path.

2022/12/13 13:16:49 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy.docx: Copied (server-side copy) to: algos_zacc/InvoiceArchive/тест/New folder/220919 - Тикети - шаблони - Copy.docx
2022/12/13 13:16:49 ERROR : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy.docx: Couldn't delete: AccessDenied: Access Denied
	status code: 403, request id: BVAE7E5NH4RF67RE, host id: K6UcjVtHWuhuAqL53rKsj0fpj6OmMZL2h7qCZp36vQ5Z+ULCyIyG7oJ0Y4otma6KDQg8upqYyqo=
2022/12/13 13:16:49 ERROR : algos_zacc/InvoiceArchive/тест/New folder/220919 - Тикети - шаблони - Copy.docx: File.Rename error: AccessDenied: Access Denied
	status code: 403, request id: BVAE7E5NH4RF67RE, host id: K6UcjVtHWuhuAqL53rKsj0fpj6OmMZL2h7qCZp36vQ5Z+ULCyIyG7oJ0Y4otma6KDQg8upqYyqo=
2022/12/13 13:16:49 ERROR : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy.docx: Dir.Rename error: AccessDenied: Access Denied
	status code: 403, request id: BVAE7E5NH4RF67RE, host id: K6UcjVtHWuhuAqL53rKsj0fpj6OmMZL2h7qCZp36vQ5Z+ULCyIyG7oJ0Y4otma6KDQg8upqYyqo=
2022/12/13 13:16:49 ERROR : IO error: AccessDenied: Access Denied
	status code: 403, request id: BVAE7E5NH4RF67RE, host id: K6UcjVtHWuhuAqL53rKsj0fpj6OmMZL2h7qCZp36vQ5Z+ULCyIyG7oJ0Y4otma6KDQg8upqYyqo=
2022/12/13 13:16:53 INFO  : vfs cache: cleaned: objects 5 (was 5) in use 0, to upload 0, uploading 0, total size 158.175Ki (was 158.175Ki)

Another example:

2022/12/14 10:52:36 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/12/14 10:53:36 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/12/14 10:54:05 INFO  : algos_zacc/InvoiceArchive/тест/New folder/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Copied (server-side copy) to: algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx
2022/12/14 10:54:05 INFO  : algos_zacc/InvoiceArchive/тест/New folder/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Deleted
2022/12/14 10:54:11 INFO  : algos_zacc/InvoiceArchive/тест/~$0919 - Тикети - шаблони - Copy337 - Copy (24).docx: vfs cache: queuing for upload in 1s
2022/12/14 10:54:12 INFO  : algos_zacc/InvoiceArchive/тест/~$0919 - Тикети - шаблони - Copy337 - Copy (24).docx: Copied (new)
2022/12/14 10:54:12 INFO  : algos_zacc/InvoiceArchive/тест/~$0919 - Тикети - шаблони - Copy337 - Copy (24).docx: vfs cache: upload succeeded try #1
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/~WRD0000.tmp: vfs cache: queuing for upload in 1s
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Copied (server-side copy) to: algos_zacc/InvoiceArchive/тест/~WRL0001.tmp
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Deleted
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: vfs cache: renamed in cache to "algos_zacc/InvoiceArchive/тест/~WRL0001.tmp"
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/~WRD0000.tmp: vfs cache: renamed in cache to "algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx"
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: vfs cache: queuing for upload in 1s
2022/12/14 10:54:17 INFO  : algos_zacc/InvoiceArchive/тест/~WRL0001.tmp: vfs cache: removed cache file as file deleted
2022/12/14 10:54:18 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Copied (new)
2022/12/14 10:54:18 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: vfs cache: upload succeeded try #1
2022/12/14 10:54:21 INFO  : algos_zacc/InvoiceArchive/тест/~$0919 - Тикети - шаблони - Copy337 - Copy (24).docx: vfs cache: removed cache file as file deleted
2022/12/14 10:54:21 ERROR : IO error: AccessDenied: Access Denied
	status code: 403, request id: ANVWVHDB5G9EJK23, host id: 7nwxKI7kcKepRw2HAqUwEm85lhSc8QT/99rNx6GZ4L/MjWq8h/x4M6wWQl63o8C5BBii7S1rpJcxFJ3wB+7Kig==
2022/12/14 10:54:25 INFO  : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Copied (server-side copy) to: algos_zacc/InvoiceArchive/тест/New folder/220919 - Тикети - шаблони - Copy337 - Copy (24).docx
2022/12/14 10:54:25 ERROR : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Couldn't delete: AccessDenied: Access Denied
	status code: 403, request id: DHHKJE9T3RCAJQ7K, host id: d8ohwjDDDaYja0mr3UQU6Trb8Bo5WovoiiNOkqOvi/UD8cQV/Rtzo28J3bJP2mLTtx57UlIo4xSDA9vgMse2xA==
2022/12/14 10:54:25 ERROR : algos_zacc/InvoiceArchive/тест/New folder/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: File.Rename error: AccessDenied: Access Denied
	status code: 403, request id: DHHKJE9T3RCAJQ7K, host id: d8ohwjDDDaYja0mr3UQU6Trb8Bo5WovoiiNOkqOvi/UD8cQV/Rtzo28J3bJP2mLTtx57UlIo4xSDA9vgMse2xA==
2022/12/14 10:54:25 ERROR : algos_zacc/InvoiceArchive/тест/220919 - Тикети - шаблони - Copy337 - Copy (24).docx: Dir.Rename error: AccessDenied: Access Denied
	status code: 403, request id: DHHKJE9T3RCAJQ7K, host id: d8ohwjDDDaYja0mr3UQU6Trb8Bo5WovoiiNOkqOvi/UD8cQV/Rtzo28J3bJP2mLTtx57UlIo4xSDA9vgMse2xA==
2022/12/14 10:54:25 ERROR : IO error: AccessDenied: Access Denied
	status code: 403, request id: DHHKJE9T3RCAJQ7K, host id: d8ohwjDDDaYja0mr3UQU6Trb8Bo5WovoiiNOkqOvi/UD8cQV/Rtzo28J3bJP2mLTtx57UlIo4xSDA9vgMse2xA==
2022/12/14 10:54:36 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 79.076Ki (was 79.076Ki)

jassenjj · December 14, 2022, 9:44am

I also managed to catch the issue with the -vv flag.
403.log (226.3 KB)

ncw · December 14, 2022, 2:44pm

This might be related to this issue

There is a fix there which you could try.

Can you try to make a sequence of steps I can try so I can reproduce the problem here?

Can you get the problem to happen from CMD or is it related to Windows Explorer only?

That strongly hints it is a timing issue doesn't it?

jassenjj · December 14, 2022, 10:06pm

Thank you for your reply.

I don't see any similarities. In my observation the issue is related to the lack of possibility to add a delay between the server-side copy and the subsequent delete operation which happens when a file is renamed or copied and pasted with Windows explorer.

There are no fixed steps to reproduce as the issue is intermittent, but it happens quite often. I'll try to make a small video and I'll add it here. For instance put a file in a folder, rename it, then drag it into a subfolder, enter there, rename it again, cut it and then paste it in the previous folder... Eventually it will generate and I/O error and duplicate entries would appear in the folder tree.

Based on my observations 1 out 5 drag and drop operations between 2 folders would fail. 1 out of 10 rename operations fails. And, of course, I have users with "special" skills who achieve this at almost any attempt.

Ole · December 15, 2022, 8:20am

Did you try the proposed fix?

Did you try replicating the issue using a small CMD/Powershell script?

You can add a delay between the requests by setting --tpslimit. The rclone default pacer has a built-in max speed equivalent to --tpslimit=100 whereas the S3 pacer has unlimited speed.

Great idea, be sure to save the corresponding debug log, so we can also see what happens behind the scenes.

That flow sounds easy to reproduce by a small CMD/Powershell script.

I guess there is more to it that just this simple usage flow - otherwise I would expect we had heard more about it - and before.

Could also depend on data (e.g. folder structure, number of files and file size) or network connection (e.g. if there are two competing routes to your S3 server so packets/requests often arrive out of sequence).

Are you able to reproduce if using a testbucket with just two folders each containing a fixed file (to make sure the folder exists in S3) and then start moving/renaming a testfile between the folders?

Are you able to reproduce if using another network connection, e.g. connect using your phone/mobile data plan?

jassenjj · December 15, 2022, 1:25pm

Hello again,

I tried the proposed fixed, it didn't help. Unfortunately, --tpslimit 1 also did not help solving the issue.
This is the video that I promised and the corresponding -vv log is attached.
403 video3.log (3.4 MB)

jassenjj · December 15, 2022, 2:48pm

And before wasting more of your time, it seems that all DELETE requests in the log, containing a versionId are failing and I have a global Deny rule to delete object versions. It is strange though why some rename operations use DELETE without versionId like this:

2022/12/15 15:04:52 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:04:52 DEBUG : HTTP REQUEST (req 0xc0007e6500)
2022/12/15 15:04:52 DEBUG : HEAD /algos_zacc/InvoiceArchive/%D1%82%D0%B5%D1%81%D1%82/45.docx HTTP/1.1
Host: algos1storage1.s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.60.1
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20221215T130452Z

2022/12/15 15:04:52 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:04:52 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:04:52 DEBUG : HTTP RESPONSE (req 0xc0007e6500)
2022/12/15 15:04:52 DEBUG : HTTP/1.1 200 OK
Content-Length: 40889
Accept-Ranges: bytes
Content-Type: application/vnd.openxmlformats-officedocument.wordprocessingml.document
Date: Thu, 15 Dec 2022 13:04:54 GMT
Etag: "9b18ff174e0576521751ccfc94cbdbe5"
Last-Modified: Thu, 15 Dec 2022 13:04:54 GMT
Server: AmazonS3
X-Amz-Id-2: b163yHYt94h/iiFbgLx7ndYL0zW8UP6CXwXwGWfrlgc1jBMej6XXodk/F7/1Gyb7g+DokcXdakU=
X-Amz-Meta-Mtime: 1671109031.6753672
X-Amz-Request-Id: 5EWPX74MD8HC1NSN
X-Amz-Version-Id: lsb4DooCTMh64boqqQdpw13zr8qVwt2P

2022/12/15 15:04:52 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:04:52 DEBUG : algos_zacc/InvoiceArchive/тест/13-7.docx: md5 = 9b18ff174e0576521751ccfc94cbdbe5 OK
2022/12/15 15:04:52 INFO  : algos_zacc/InvoiceArchive/тест/13-7.docx: Copied (server-side copy) to: algos_zacc/InvoiceArchive/тест/45.docx
2022/12/15 15:04:52 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:04:52 DEBUG : HTTP REQUEST (req 0xc0005d3900)
2022/12/15 15:04:52 DEBUG : DELETE /algos_zacc/InvoiceArchive/%D1%82%D0%B5%D1%81%D1%82/13-7.docx HTTP/1.1
Host: algos1storage1.s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.60.1
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20221215T130452Z
Accept-Encoding: gzip

2022/12/15 15:04:52 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:04:52 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:04:52 DEBUG : HTTP RESPONSE (req 0xc0005d3900)
2022/12/15 15:04:52 DEBUG : HTTP/1.1 204 No Content
Date: Thu, 15 Dec 2022 13:04:54 GMT
Server: AmazonS3
X-Amz-Delete-Marker: true
X-Amz-Id-2: h4nhKYA4gKpoBfDVFY5AfPYU5DbZH/kPXHzivpcgIKTIl/OwsXFrUB2btrf7yhgRRTrB6gblud4=
X-Amz-Request-Id: 5EWXXJPZESGWGTFV
X-Amz-Version-Id: D_fZJ0bIR6KOsIDpedE8tVj2wcwcz30i

2022/12/15 15:04:52 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

and others insist on using a versionId:

2022/12/15 15:05:19 DEBUG : HTTP REQUEST (req 0xc0003f7c00)
2022/12/15 15:05:19 DEBUG : PUT /algos_zacc/InvoiceArchive/%D1%82%D0%B5%D1%81%D1%82/New%20folder/57.docx HTTP/1.1
Host: algos1storage1.s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.60.1
Content-Length: 0
Authorization: XXXX
X-Amz-Acl: private
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Copy-Source: algos1storage1/algos_zacc/InvoiceArchive/%D1%82%D0%B5%D1%81%D1%82/New%20folder/45.docx?versionId=D.iBDxoW8zqKaT9CnTaaoztn4ms7dttT
X-Amz-Date: 20221215T130519Z
X-Amz-Metadata-Directive: COPY
Accept-Encoding: gzip

2022/12/15 15:05:19 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:05:19 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:05:19 DEBUG : HTTP RESPONSE (req 0xc0003f7c00)
2022/12/15 15:05:19 DEBUG : HTTP/1.1 200 OK
Content-Length: 234
Content-Type: application/xml
Date: Thu, 15 Dec 2022 13:05:21 GMT
Server: AmazonS3
X-Amz-Copy-Source-Version-Id: D.iBDxoW8zqKaT9CnTaaoztn4ms7dttT
X-Amz-Id-2: zt0ft/zQz6EU1OSJFI2cRAiRSy7gAcS1IARw6CvsSr0nEjC/CPtViEEYbJGZ+YdG0ouNoX/NCv0=
X-Amz-Request-Id: TAB784KSA1E7N7QJ
X-Amz-Version-Id: Wq3K64N4qcTTOpPepufuTtLcxQW0lUFv

2022/12/15 15:05:19 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:05:19 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:05:19 DEBUG : HTTP REQUEST (req 0xc00090ae00)
2022/12/15 15:05:19 DEBUG : HEAD /algos_zacc/InvoiceArchive/%D1%82%D0%B5%D1%81%D1%82/New%20folder/57.docx HTTP/1.1
Host: algos1storage1.s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.60.1
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20221215T130519Z

2022/12/15 15:05:19 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:05:19 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:05:19 DEBUG : HTTP RESPONSE (req 0xc00090ae00)
2022/12/15 15:05:19 DEBUG : HTTP/1.1 200 OK
Content-Length: 40904
Accept-Ranges: bytes
Content-Type: application/vnd.openxmlformats-officedocument.wordprocessingml.document
Date: Thu, 15 Dec 2022 13:05:21 GMT
Etag: "3250531e253032c239c7cb02472f8eda"
Last-Modified: Thu, 15 Dec 2022 13:05:21 GMT
Server: AmazonS3
X-Amz-Id-2: DpuY28ZOBjKtl858a0iRzJkWX6uQxigDx5sl2W5WAjlmASZSjGIeTLZvzdilZb01QlZXk1wXZwg=
X-Amz-Meta-Mtime: 1671109504.9941464
X-Amz-Request-Id: TABD6HFNGCCE0NM8
X-Amz-Version-Id: Wq3K64N4qcTTOpPepufuTtLcxQW0lUFv

2022/12/15 15:05:19 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:05:19 DEBUG : algos_zacc/InvoiceArchive/тест/New folder/45.docx: md5 = 3250531e253032c239c7cb02472f8eda OK
2022/12/15 15:05:19 INFO  : algos_zacc/InvoiceArchive/тест/New folder/45.docx: Copied (server-side copy) to: algos_zacc/InvoiceArchive/тест/New folder/57.docx
2022/12/15 15:05:19 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:05:19 DEBUG : HTTP REQUEST (req 0xc0005d2a00)
2022/12/15 15:05:19 DEBUG : DELETE /algos_zacc/InvoiceArchive/%D1%82%D0%B5%D1%81%D1%82/New%20folder/45.docx?versionId=D.iBDxoW8zqKaT9CnTaaoztn4ms7dttT HTTP/1.1
Host: algos1storage1.s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.60.1
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20221215T130519Z
Accept-Encoding: gzip

2022/12/15 15:05:19 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/12/15 15:05:19 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/12/15 15:05:19 DEBUG : HTTP RESPONSE (req 0xc0005d2a00)
2022/12/15 15:05:19 DEBUG : HTTP/1.1 403 Forbidden
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Thu, 15 Dec 2022 13:05:20 GMT
Server: AmazonS3
X-Amz-Id-2: AaB+iyuXBWAOTUTULqci9wdrDkCDGVmz/OMFF1Oybdn8JrnqgzRoSQDzV5XHtafNJQ45RxNv8Ic=
X-Amz-Request-Id: TABCEND59TN4605S

2022/12/15 15:05:19 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

ncw · December 15, 2022, 3:54pm

Well spotted.

I'm not familiar with that tech. Is that an S3 setting?

It's probably something like files which existed when rclone started won't have the versionId but files which were uploaded by rclone will.

If you aren't using --s3-versions or --s3-version-at you won't get versions in the listings but you will get versions returned on uploads etc.

Maybe rclone should be ignoring these if it isn't using versions - I'm not sure.

jassenjj · December 15, 2022, 5:10pm

Yes, all possible S3 operations are access controlled individually by every possible criteria (users, paths, access points, IP addresses, interfaces and many others). Deleting an object version requires the s3:DeleteObjectVersion policy to be allowed for the specific user at the specific path (and the possible other conditions that can be added are practically endless). In my company there is a global Deny rule on deleting object versions as a security measure - the users operate only with the latest versions of the files and all previous versions remain available for 5+ years even for deleted files.

Regardless of the setup in my company, specifying versions when not using --s3-versions mode guarantees consistency, but it requires a whole new set of permissions and the corresponding maintenance. It would also allow a user to rename a non existent file, to copy a version which is not the latest or even to delete an object version unintentionally.

Clearly, with --s3-versions specifying the versionId should be considered mandatory.

IMO, there is no universal solution to the issue once versions support is introduced with rclone. The optimal solution would be the object versionId-s to be managed on operation basis (example: separate control for copy and delete operations) and as a minimum there should be a way to access an S3 drive as version-unaware storage.

ncw · December 15, 2022, 6:13pm

Thanks for explaining.

I'm reasonably sure that what is happening here is when rclone uploads an object it is getting the versionId from AWS at that point.

So if you try to delete an object that you uploaded then rclone will use the versionId.

I think that if you don't use --s3-versions or --s3-version-at then rclone should behave as version unaware and not store versionIDs for objects.

I think this would fix your problem.

What do you think? Shall I give it a go?

jassenjj · December 15, 2022, 6:17pm

I would agree that this would solve my issue. If you believe it is OK, please give it a go.
Thank you for the prompt response.

zerkms · December 15, 2022, 10:51pm

After upgrading to 1.60.1 I started experiencing the same problem. 1.58.1 runs with no issues

2022/12/15 22:47:30 ERROR : <redacted-filename>: Failed to copy: Forbidden: Forbidden                                                                                                        
    status code: 403, request id: BZ4QZKGPCHYEB9FN, host id: 9quj8ptc1xNLs2GoPw7dJ/0pmlJ3fSU3p8E90eRP4wBty0VTJzgJsXUs4y7opwjL4JYl0BUJlfJbyVOYlpqG8g==                                                                                                                                     
2022/12/15 22:47:30 ERROR : Encrypted drive 'dest:': not deleting files as there were IO errors                                                                                                                                                                                           
2022/12/15 22:47:30 ERROR : Encrypted drive 'dest:': not deleting directories as there were IO errors                                                                                                                                                                                     
2022/12/15 22:47:30 ERROR : Attempt 1/3 failed with 1 errors and: Forbidden: Forbidden                                                                                                                                                                                                    
    status code: 403, request id: BZ4QZKGPCHYEB9FN, host id: 9quj8ptc1xNLs2GoPw7dJ/0pmlJ3fSU3p8E90eRP4wBty0VTJzgJsXUs4y7opwjL4JYl0BUJlfJbyVOYlpqG8g==                                                                                                                                     
2022/12/15 22:47:31 INFO  :                                                                                                                                                                                                                                                               
Transferred:         553.027 KiB / 553.027 KiB, 100%, 276.060 KiB/s, ETA 0s                                                                                                                                                                                                               
Checks:             93348 / 93348, 100%                                                                                                                                                                                                                                                   
Elapsed time:       1m0.2s

ncw · December 16, 2022, 11:58am

Please give this a go - I think it should solve your problem @jassenjj and @zerkms

v1.61.0-beta.6650.bb211993b.fix-s3-no-versions on branch fix-s3-no-versions (uploaded in 15-30 mins)

ncw · December 17, 2022, 10:25am

I've merged this to master now as I want to get it in before the new release which means it will be in the latest beta in 15-30 minutes and released in v1.61.

I'm still interested in reports of whether it works for you though!

jassenjj · December 19, 2022, 2:22pm

Hello, again,
I am now using this version and I'll give you feedback if necessary.
Thank you!

zerkms · December 19, 2022, 8:13pm

@ncw thanks for that: I can confirm that I have run it successfully a few times with no problems!

zerkms · December 21, 2022, 1:52am

v1.61.0 runs great too, thanks again!

system · January 20, 2023, 1:53am

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