search

archiecobbs / s3backer

FUSE/NBD single file backing store via Amazon S3
Other
535 stars 77 forks source link

Stream error in the HTTP/2 framing layer #168

Closed solracsf closed 2 years ago

solracsf commented 2 years ago

I'm having quite a lot of operation failed: Stream error in the HTTP/2 framing layer (will retry) in my logs.

This message comes from CURLE_HTTP2_STREAM and there are a few reports, all closed, on the curl repo. Some of them were fixed upstream, others on the program calling curl itself.

To exclude any bug in curl itself, I've compiled curl and nghttp2 from source to their latest releases, but errors remains.

# curl -V
curl 7.81.0 (x86_64-pc-linux-gnu) libcurl/7.81.0 OpenSSL/1.1.1f zlib/1.2.11 libssh2/1.8.0 nghttp2/1.46.0
Release-Date: 2022-01-05
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTP2 HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL TLS-SRP UnixSockets

The only "workaround fix' was disabling HTTP/2 negotiation by setting CURLOPT_SSL_ENABLE_ALPN and CURLOPT_SSL_ENABLE_NPN to 0 on http_io.c

Excerpt form --debug log (1sec window):

Feb  2 10:07:54 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/33c1894d/0000a445
Feb  2 10:07:54 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/f3f87442/0000a444
Feb  2 10:07:54 nbg1-s3backer s3backer: operation failed: Stream error in the HTTP/2 framing layer (will retry)
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8abea5d8/000010b4
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/3267eb46/0000a437
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/f77e4f07/000010b5
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8a7efbd7/0000a438
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/849c3cd9/000000b6
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8ae2b9bd/0000a43f
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/9f92c69d/000010b6
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/48302460/0000a440
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/24d4bb75/0000a442
Feb  2 10:07:54 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/fa3f0def/0000a441
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/68d7f329/0000a43d
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/09dc9869/0000a434
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/fa68bb46/0000a43e
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/bcc2b359/0000a43c
Feb  2 10:07:54 nbg1-s3backer s3backer: retrying query (attempt #2): GET https://scw-test-s3b.s3.fr-par.scw.cloud/c592e58a/0000a446
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/748cb250/0000a42f
Feb  2 10:07:54 nbg1-s3backer s3backer: operation failed: Stream error in the HTTP/2 framing layer (will retry)
Feb  2 10:07:54 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/c592e58a/0000a446
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8bb63cec/0000a435
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/41d92572/000000b4
Feb  2 10:07:54 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/48302460/0000a440
Feb  2 10:07:54 nbg1-s3backer s3backer: retrying query (attempt #2): GET https://scw-test-s3b.s3.fr-par.scw.cloud/fddd6265/0000a443
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/849c3cd9/000000b6
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/fa3f0def/0000a441
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8a359016/000000b5
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/fddd6265/0000a443
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/71110c28/0000a447
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/953d0fff/0000a448
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/ff1f00c8/0000a449
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/2e975ca6/0000a44a
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/f77e4f07/000010b5
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/71110c28/0000a447
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/96e61a29/0000a44b
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/953d0fff/0000a448
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/e1b2b83c/0000a44c
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/2e975ca6/0000a44a
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/ff1f00c8/0000a449
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/32f569c0/0000a44d
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/18dbc03e/0000a44e
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/96e61a29/0000a44b
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/3b6758a0/0000a44f
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/24d4bb75/0000a442
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/33c1894d/0000a445
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/fddd6265/0000a443
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/f3f87442/0000a444
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/c592e58a/0000a446
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/32f569c0/0000a44d
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/18dbc03e/0000a44e
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/e1b2b83c/0000a44c
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/883ced3c/0000a450
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/ea4809d8/0000a451
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/9f92c69d/000010b6
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/f37946a5/0000a452
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8ae2b9bd/0000a43f
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/71110c28/0000a447
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/953d0fff/0000a448
Feb  2 10:07:55 nbg1-s3backer s3backer: success: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/8abea5d8/000010b4
Feb  2 10:07:55 nbg1-s3backer s3backer: rec'd 404 response: GET https://scw-test-s3b.s3.fr-par.scw.cloud/3b6758a0/0000a44f
Feb  2 10:07:55 nbg1-s3backer s3backer: GET https://scw-test-s3b.s3.fr-par.scw.cloud/36139650/0000a453
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/ff1f00c8/0000a449
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/96e61a29/0000a44b
Feb  2 10:07:55 nbg1-s3backer s3backer: PUT https://scw-test-s3b.s3.fr-par.scw.cloud/2e975ca6/0000a44a
Feb  2 10:07:55 nbg1-s3backer s3backer: operation failed: Stream error in the HTTP/2 framing layer (will retry)
archiecobbs commented 2 years ago

Hmm.. I have no idea what to do about this (or even what it means).

We already close a CURL handle when we get any errors on it, so that logic is already in place.

You could try enabling -f --debug --http-debug and sending the logs to the CURL team. Of course the logs could be voluminous so this would benefit from a minimal test case.

GreenBlood commented 2 years ago

Hey @acsfer Same problem here when doing high write operations.

However I'm noticing one thing : We both use scaleway object storage, and I did not notice errors before recently. It could mean that the error is not directly from s3backer or curl, but maybe from Scaleway S3 itself (linked to the new multi-az bucket feature maybe ?)

solracsf commented 2 years ago

AWS doesn't use HTTP/2, maybe there is a good reason to this ;) That's why we've disabled it. But maybe reach Scaleway on this (we are just testing).

GreenBlood commented 2 years ago

After some investigation, and being on FreeBSD I re-compiled curl without the HTTP2 support and everything works fine. So I think the error indeed lies in Scaleway and its handling of HTTP2 (I heard that there was special behaviour on AWS with load balancers and such aswell.)

It's not a huge need for me, I use s3backer as a kinda-NAS only but I'll try and contact the support team nonetheless.

@archiecobbs I'm not sure about what power you have on this matter regarding libcurl, but would it be useful to fallback to http1.1 incase of such protocol errors ? I'm not sure about your software behaviour in this case, and I was afraid that some PUT would not go through and would be lost at some point.

archiecobbs commented 2 years ago

@GreenBlood s3backer already closes the current CURL handle and retries on HTTP errors, so the impact of this issue should be minimal.

In any case I'm not sure what else there would be for s3backer to do anyway.

solracsf commented 2 years ago

Some software (like rclone) has an option like --disable-http2 to handle these cases, by disabling it's negotiation (just like I did - see my 1st post). This is the only thing that could be done s3backer side (beside retries).

Feel free to close this as this is NOT a direct s3backer issue.

archiecobbs commented 2 years ago

I've added --http11 to restrict CURL to HTTP 1.1. See if that works around the problem.

solracsf commented 2 years ago

Perfect ❤️