error zeroing blocks: Success

[khumarahn]

Hi. I've been using s3backer for quite some time with great success, thank you.

Now I'm trying to make it work with zfs, mostly out of curiosity if it will work better. I get a lot of strange errors of the type:

Oct 07 23:46:43 localhost nbdkit[1250]: s3backer: rec'd 403 response: POST https://bbb.s3.fr-par.scw.cloud/?delete
Oct 07 23:46:43 localhost nbdkit[1250]: s3backer.9: error zeroing 2 block(s) starting at 0000010b: Success
Oct 07 23:46:43 localhost kernel: block nbd4: Other side returned error (1)
Oct 07 23:46:43 localhost kernel: blk_update_request: I/O error, dev nbd4, sector 8520 op 0x3:(DISCARD) flags 0x800 phys_seg 1 prio class 0

[khumarahn]

An easy way to reliably reproduce this is blkdiscard -f /dev/nbd4. It fails with lots of errors in the system log and this in console:

blkdiscard: Operation forced, data will be lost!
blkdiscard: /dev/nbd4: BLKDISCARD ioctl failed: Input/output error

In turn, blkdiscard -f -z /dev/nbd4 works correctly

[khumarahn]

Probably it has nothing to do with zfs. This is a simple way to reproduce:

# dd if=/dev/urandom of=/dev/nbd4 bs=1M count=8
8+0 records in
8+0 records out
8388608 bytes (8.4 MB, 8.0 MiB) copied, 3.62839 s, 2.3 MB/s

# blkdiscard /dev/nbd4 
blkdiscard: /dev/nbd4: BLKDISCARD ioctl failed: Input/output error

Files in the bucket are not deleted

[archiecobbs]

What version are you using? This might be due to issue #208. Can you try it with release 2.1.0 if not already?

[khumarahn]

What version are you using? This might be due to issue #208. Can you try it with release 2.1.0 if not already?

# s3backer --version
s3backer version 2.1.0 ()
Copyright (C) 2008-2020 Archie L. Cobbs.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

By the way, it is nearly 2024 :-)

[khumarahn]

I'm also not using encryption or compression, as in #208. My config, just in case:

--force
--size=500G
--blockSize=16K
--listBlocks
--accessFile=access.file
--baseURL=https://s3.fr-par.scw.cloud/
--region=fr-par
--blockCacheSize=0
--timeout=300
--initialRetryPause=5000
--maxRetryPause=300000

[archiecobbs]

Looks like this might be another Amazon vs. 3rd party compatibility issue. Can you go through the same debug sequence as in #208?

• See if you can reproduce the bug when using Amazon instead of scw.cloud.
• Enable HTTP debug logs running in foreground to see what actual HTTP error is being returned

[khumarahn]

Yeap, I can immediately try it with -f --debug-http. Here is the log: a.log

I never used amazon services, so I'm not sure I can quickly try that

Upd: this is probably the relevant part of the log

Oct 08 19:36:10 s3backer[84439]: * Re-using existing connection with host bebucket.s3.fr-par.scw.cloud
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] OPENED stream for https://bebucket.s3.fr-par.scw.cloud/?delete
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [:method: GET]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [:scheme: https]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [:authority: bebucket.s3.fr-par.scw.cloud]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [:path: /?delete]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [user-agent: s3backer/2.1.0/]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [accept: */*]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [accept-encoding: deflate, gzip]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [x-amz-date: 20231008T173610Z]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855]
Oct 08 19:36:10 s3backer[84439]: * [HTTP/2] [5] [authorization: AWS4-HMAC-SHA256 Credential=SCW82JJ9PFMCARJ7NMHQ/20231008/fr-par/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=c9021338f61e6ef7d38402eca7afe239a91f3b6abb384db76b94d28421594fe6]
Oct 08 19:36:10 s3backer[84439]: > GET /?delete HTTP/2
Oct 08 19:36:10 s3backer[84439]: Host: bebucket.s3.fr-par.scw.cloud
Oct 08 19:36:10 s3backer[84439]: User-Agent: s3backer/2.1.0/
Oct 08 19:36:10 s3backer[84439]: Accept: */*
Oct 08 19:36:10 s3backer[84439]: Accept-Encoding: deflate, gzip
Oct 08 19:36:10 s3backer[84439]: x-amz-date: 20231008T173610Z
Oct 08 19:36:10 s3backer[84439]: x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
Oct 08 19:36:10 s3backer[84439]: Authorization: AWS4-HMAC-SHA256 Credential=SCW82JJ9PFMCARJ7NMHQ/20231008/fr-par/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=c9021338f61e6ef7d38402eca7afe239a91f3b6abb384db76b94d28421594fe6
Oct 08 19:36:10 s3backer[84439]: 
Oct 08 19:36:10 s3backer[84439]: < HTTP/2 403
Oct 08 19:36:10 s3backer[84439]: < x-amz-id-2: tx9711675e14d84c98913fe-006522e88a
Oct 08 19:36:10 s3backer[84439]: < x-amz-request-id: tx9711675e14d84c98913fe-006522e88a
Oct 08 19:36:10 s3backer[84439]: < content-type: application/xml
Oct 08 19:36:10 s3backer[84439]: < date: Sun, 08 Oct 2023 17:36:10 GMT
Oct 08 19:36:10 s3backer[84439]: <
Oct 08 19:36:10 s3backer[84439]: * Connection #1 to host bebucket.s3.fr-par.scw.cloud left intact
Oct 08 19:36:10 s3backer[84439]: 2023-10-08 19:36:10 ERROR: rec'd 403 response: POST https://bebucket.s3.fr-par.scw.cloud/?delete
Oct 08 19:36:10 s3backer[84439]: nbdkit: s3backer.3: error: error zeroing 16383 block(s) starting at 00000000: Success

[khumarahn]

By the way, where in the delete request above is the number of the block to delete?

[khumarahn]

I have set up an amazon s3 bucket, same error

[khumarahn]

Here is the amazon log: a.log

Oct 08 20:09:17 s3backer[84946]: * Re-using existing connection with host abebaka.s3.eu-west-2.amazonaws.com
Oct 08 20:09:17 s3backer[84946]: > GET /?delete HTTP/1.1
Oct 08 20:09:17 s3backer[84946]: Host: abebaka.s3.eu-west-2.amazonaws.com
Oct 08 20:09:17 s3backer[84946]: User-Agent: s3backer/2.1.0/
Oct 08 20:09:17 s3backer[84946]: Accept: */*
Oct 08 20:09:17 s3backer[84946]: Accept-Encoding: deflate, gzip
Oct 08 20:09:17 s3backer[84946]: x-amz-date: 20231008T180917Z
Oct 08 20:09:17 s3backer[84946]: x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
Oct 08 20:09:17 s3backer[84946]: Authorization: AWS4-HMAC-SHA256 Credential=AKIAY6OQO4BHQ2474IT5/20231008/eu-west-2/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=39dbd972605f1aab68b2f18fbeaf36338db26535f0074b6934c346abc53bc0ec
Oct 08 20:09:17 s3backer[84946]: 
Oct 08 20:09:17 s3backer[84946]: < HTTP/1.1 403 Forbidden
Oct 08 20:09:17 s3backer[84946]: < x-amz-request-id: FWY4GFT7V4CQQYTF
Oct 08 20:09:17 s3backer[84946]: < x-amz-id-2: FoPslufxrrk4SLXfG6nrneqKd7tH6liAHToOQPOMqs2IJn/1LYHZAorDDZaSPRjHIdij7hn0pro=
Oct 08 20:09:17 s3backer[84946]: < Content-Type: application/xml
Oct 08 20:09:17 s3backer[84946]: < Transfer-Encoding: chunked
Oct 08 20:09:17 s3backer[84946]: < Date: Sun, 08 Oct 2023 18:09:17 GMT
Oct 08 20:09:17 s3backer[84946]: < Server: AmazonS3
Oct 08 20:09:17 s3backer[84946]: <
Oct 08 20:09:17 s3backer[84946]: * Connection #1 to host abebaka.s3.eu-west-2.amazonaws.com left intact
Oct 08 20:09:17 s3backer[84946]: 2023-10-08 20:09:17 ERROR: rec'd 403 response: POST https://abebaka.s3.eu-west-2.amazonaws.com/?delete
Oct 08 20:09:17 s3backer[84946]: nbdkit: s3backer.3: error: error zeroing 16383 block(s) starting at 00000000: Success

[archiecobbs]

By the way, where in the delete request above is the number of the block to delete?

It's in the payload of the request, which is not shown.

But there is something weird going on. Your log shows:

GET /?delete HTTP/2

but that should be a POST not a GET.

I will try to reproduce...

[khumarahn]

I tried adding encryption and compression to my config. The error looks the same

--encrypt
--passwordFile=whatever
--compress=7

[khumarahn]

Ah, I found how to make blkdiscard work: it works with block cache file enabled.

[khumarahn]

Now I perhaps understand why I wasn't hitting this problem before. I only attempted to disable block cache file recently as an experiment, following the advice in https://github.com/archiecobbs/s3backer/blob/master/README_nbd.md

[archiecobbs]

Please try 02a6f19 and let me know if this fixes the problem. Thanks.

[khumarahn]

That worked. At least, the simple test passes. I'll give it a try more seriously soon

Much YAY

[archiecobbs]

Great, thanks for the bug report & for testing the fix.