Libcurl reports 'Error in the HTTP2 framing layer' (16) for outgoing request.

[Shikha Sharma via curl-library]

Hello,

I am facing an issue where curls responds with error "'Error in the
HTTP2 framing layer' (16)" to the application.

Curl version: libcurl-7.74.0

Scenario: Sending multiple outgoing HTTP2 requests to an external HTTP
server.

Issue: The first request is processed okay and then randomly some
request start reporting the above error. The server responds with GoAway
frame after each response.

So it looks as if its a race condition where the client starts
processing the new request and creates a stream on the existing
connection before the goaway frame from the previous connection is
processed. The request is ultimately dropped and application using
libcurl receives the framing error.

The verbose output for curl is as below:

* 17 bytes stray data read before trying h2 connection
* Found bundle for host 127.0.0.1: 0x7fbc08011db0 [can multiplex]
* Hostname 127.0.0.1 was found in DNS cache
*   Trying 127.0.0.1:10001...
* Connected to 127.0.0.1 (127.0.0.1) port 10001 (#55)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after
upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fbc08000a30)

POST /nausf-auth/v1/ue-authentications HTTP/2

Host: 127.0.0.1:10001
user-agent: bf-am-http
accept: application/json
cache-control: no-cache
content-type: application/json
content-length: 106

* We are completely uploaded and fine
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 201
< content-type: application/json
< location:
http://192.168.56.101:8001/nausf-auth/v1/ue-authentications/suci-0-208-93-0000-0-0-0000000003

< content-length: 366
< date: Wed, 26 May 2021 12:16:58 GMT
<
* Connection #55 to host 127.0.0.1 left intact
* Found bundle for host 127.0.0.1: 0x7fbc08011db0 [can multiplex]
* 17 bytes stray data read before trying h2 connection
* Re-using existing connection! (#55) with host 127.0.0.1
* Connected to 127.0.0.1 (127.0.0.1) port 10001 (#55)
* Using Stream ID: 3 (easy handle 0x7fbc08000a30)

POST /nausf-auth/v1/ue-authentications HTTP/2

Host: 127.0.0.1:10001
user-agent: bf-am-http
accept: application/json
cache-control: no-cache
content-type: application/json
content-length: 106

* stopped the pause stream!
* Closing connection 55

The next request after this works fine.

The screenshot of pcap is attached.

Is there a way this race condition/ error can be avoided?

Please let me know if more information is needed for this.


Regards,

Shikha

[Daniel Stenberg via curl-library]

I am facing an issue where curls responds with error "'Error in the HTTP2
framing layer' (16)" to the application.
Curl version: libcurl-7.74.0
Scenario: Sending multiple outgoing HTTP2 requests to an external HTTP
server.

I'm afraid this descripion lacks details to allow us to draw many conclusions.
You also didn't mention if you use h2 over TLS or not and you didn't state
which nghttp2 version you're using.

So it looks as if its a race condition where the client starts processing
the new request and creates a stream on the existing connection before the
goaway frame from the previous connection is processed. The request is
ultimately dropped and application using libcurl receives the framing error.

If that's true then it sounds like a bug to me. We've fixed several h2 related
bugs since 7.74.0 so I'd recommand you start out by trying the latest curl
version and see if anything gets better.

[Shikha Sharma via curl-library]

Thanks for your reply.

I tried it with the latest version and unfortunately it still doesnt work.

curl -V
curl 7.77.0 (x86_64-redhat-linux-gnu) libcurl/7.77.0 NSS/3.53.1
zlib/1.2.7 libpsl/0.7.0 (+libicu/50.1.2) libssh2/1.9.0 nghttp2/1.39.1
OpenLDAP/2.4.44 libmetalink/0.1.3
Release-Date: 2021-05-26
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap
ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS GSS-API HSTS HTTP2 HTTPS-proxy IPv6 Kerberos
Largefile libz Metalink NTLM NTLM_WB PSL SPNEGO SSL UnixSockets

HTTP2 connection with prior knowledge initiated by curl, No TLS. Server
sends GoAway frame after processing each request.

Post by Daniel Stenberg via curl-library

Post by Shikha Sharma via curl-library
I am facing an issue where curls responds with error "'Error in the
HTTP2 framing layer' (16)" to the application.
Curl version: libcurl-7.74.0
Scenario: Sending multiple outgoing HTTP2 requests to an external
HTTP server.

I'm afraid this descripion lacks details to allow us to draw many
conclusions. You also didn't mention if you use h2 over TLS or not and
you didn't state which nghttp2 version you're using.

Post by Shikha Sharma via curl-library
So it looks as if its a race condition where the client starts
processing the new request and creates a stream on the existing
connection before the goaway frame from the previous connection is
processed. The request is ultimately dropped and application using
libcurl receives the framing error.

If that's true then it sounds like a bug to me. We've fixed several h2
related bugs since 7.74.0 so I'd recommand you start out by trying the
latest curl version and see if anything gets better.

Addiing curl verbose logs of couple of curl requests, 1 is okay, 2nd
fails and 3rd is okay again.

I * Too old connection (172 seconds), disconnect it
* Connection 90 seems to be dead!
* Closing connection 90
* Hostname in DNS cache was stale, zapped
*   Trying 127.0.0.1:10001...
* Connected to 127.0.0.1 (127.0.0.1) port 10001 (#91)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after
upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fbc08000a30)

Post by Daniel Stenberg via curl-library
POST /nausf-auth/v1/ue-authentications HTTP/2

Host: 127.0.0.1:10001
user-agent: bf-am-http
accept: application/json
cache-control: no-cache
content-type: application/json
content-length: 106

* We are completely uploaded and fine
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 201
< content-type: application/json
< location:
http://192.168.56.101:8001/nausf-auth/v1/ue-authentications/suci-0-208-93-0000-0-0-0000000003
< content-length: 366
< date: Thu, 27 May 2021 12:22:20 GMT
<
* Connection #91 to host 127.0.0.1 left intact
--------------------------------------------------<Connection not marked
as closed yet>-------------------------
* Found bundle for host 127.0.0.1: 0x7fbc08007680 [can multiplex]
* 17 bytes stray data read before trying h2 connection
* Re-using existing connection! (#91) with host 127.0.0.1
* Connected to 127.0.0.1 (127.0.0.1) port 10001 (#91)
* Using Stream ID: 3 (easy handle 0x7fbc08000a30)
----------------------------------------------------<created new
stream>------------------------------------------------------

Post by Daniel Stenberg via curl-library
POST /nausf-auth/v1/ue-authentications HTTP/2

Host: 127.0.0.1:10001
user-agent: bf-am-http
accept: application/json
cache-control: no-cache
content-type: application/json
content-length: 106

* stopped the pause stream!
------------------------------------------------------<Goaway processed?>
* Closing connection 91
* Hostname 127.0.0.1 was found in DNS cache
*   Trying 127.0.0.1:10001...
* Connected to 127.0.0.1 (127.0.0.1) port 10001 (#92)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after
upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fbc08000a30)

Post by Daniel Stenberg via curl-library
POST /nausf-auth/v1/ue-authentications HTTP/2

Host: 127.0.0.1:10001
user-agent: bf-am-http
accept: application/json
cache-control: no-cache
content-type: application/json
content-length: 106

* We are completely uploaded and fine
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 201
< content-type: application/json
< location:
http://192.168.56.101:8001/nausf-auth/v1/ue-authentications/suci-0-208-93-0000-0-0-0000000003
< content-length: 366
< date: Thu, 27 May 2021 12:22:21 GMT
<
* Closing connection 92 ---------------------------------------Here
connection marked as closed already-------------------------------
* Hostname 127.0.0.1 was found in DNS cache
*   Trying 127.0.0.1:10001...
* Connected to 127.0.0.1 (127.0.0.1) port 10001 (#93)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after
upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fbc08000a30)

Post by Daniel Stenberg via curl-library
POST /nausf-auth/v1/ue-authentications HTTP/2

Host: 127.0.0.1:10001
user-agent: bf-am-http
accept: application/json
cache-control: no-cache
content-type: application/json
content-length: 106

* We are completely uploaded and fine
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 201
< content-type: application/json
< location:
http://192.168.56.101:8001/nausf-auth/v1/ue-authentications/suci-0-208-93-0000-0-0-0000000003
< content-length: 366
< date: Thu, 27 May 2021 12:22:21 GMT
<
* Closing connection 93



-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquett

[Daniel Stenberg via curl-library]

HTTP2 connection with prior knowledge initiated by curl, No TLS. Server sends
GoAway frame after processing each request.

I suspect the problem/bug here is that the request that reads the trailing
GOAWAY isn't properly considered as a "dead connection" to get retried on a
new connection.

Have you figured out a way to reproduce this issue against public URL with
a small code snippet that you can share with us?

[Shikha Sharma via curl-library]

Post by Daniel Stenberg via curl-library

Post by Shikha Sharma via curl-library
HTTP2 connection with prior knowledge initiated by curl, No TLS.
Server sends GoAway frame after processing each request.

I suspect the problem/bug here is that the request that reads the
trailing GOAWAY isn't properly considered as a "dead connection" to
get retried on a new connection.

That is indeed the issue as verified by the debug logs.

Post by Daniel Stenberg via curl-library
Have you figured out a way to reproduce this issue against public URL
with a small code snippet that you can share with us?

I am still working on the URL (http server) against which we can test
it. Will provide it as soon as I have it ready.

Meanwhile, I used a simple http_client to send 2 send requests.

 code is available@
https://github.com/SharmaShikha-84/Http2-Client/blob/main/http2_client.c

The debugging trace after reproducing the scenario is available at:

https://github.com/SharmaShikha-84/Http2-Client/blob/main/Error_log.txt

As per the logs below:

* http2_recv: easy 0x7ef890 (stream 0) win 33553522/4294967295
* h2_process_pending_input: All data in connection buffer processed
* http2_recv returns 0, http2_handle_stream_close
* Connection #0 to host 192.168.99.199 left intact
* Found bundle for host 192.168.99.199: 0x7f83f0 [can multiplex]
* 17 bytes stray data read before trying h2 connection
----------------------------------(Goaway received here )
* h2_process_pending_input: All data in connection buffer processed
* h2_process_pending_input: nothing to do in this session
-----------------------------------(Should have been closed here)
* Re-using existing connection! (#0) with host 192.168.99.199
-----------------------------------(Connection reused even after goaway)
* Connected to 192.168.99.199 (192.168.99.199) port 8000 (#0)
* http2_send len=117
* h2 header: :method:GET
* h2 header:
:path:/nnrf-nfm/v1/nf-instances/e219be29-c62c-4710-a8d5-4e48680a6080
* h2 header: :scheme:http
* h2 header: :authority:192.168.99.199:8000
* h2 header: accept:*/*
* http2_send request allowed 0 (easy handle 0x7ef890)
-------------------------------------(Request not allowed anymore still
nghttp2_submit called)
* Using Stream ID: 3 (easy handle 0x7ef890)
* on_stream_close(), REFUSED_STREAM (err 7), stream 3
--------------------------------------( As a result stream is refused )

Proposed solution:

curl -V
curl 7.74.0 (x86_64-redhat-linux-gnu) libcurl/7.74.0 NSS/3.44 zlib/1.2.7
libpsl/0.7.0 (+libicu/50.1.2) libssh2/1.8.0 nghttp2/1.39.1
Release-Date: 2020-12-09
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps
mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS GSS-API HTTP2 HTTPS-proxy IPv6 Kerberos
Largefile libz Metalink NTLM NTLM_WB PSL SPNEGO SSL UnixSocketsution:

--- http2_modified.c  2021-06-03 16:44:31.097874213 +0200
+++ http2.c    2021-06-03 16:46:30.203469531 +0200
@@ -199,7 +199,11 @@
               (int)nread);
         httpc->nread_inbuf = 0;
         httpc->inbuflen = nread;
-        (void)h2_process_pending_input(conn, httpc, &result);
+        if (h2_process_pending_input(conn, httpc, &result) < 0)
+        {
+            /* connection can be closed */
+            dead = TRUE;
+        }
       }
       else
         /* the read failed so let's say this is dead anyway */


Trace after fix:

https://github.com/SharmaShikha-84/Http2-Client/blob/main/Trace_after_fix

Regards,

Shikha

-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://cu

[Daniel Stenberg via curl-library]

Ah, yes that looks interesting - especially since it fixes the problem for
you! Are you able to make a pull-request out of that and submit, or would you
like me to do it for you? Thanks!

[Jeroen Ooms via curl-library]

On Thu, Jun 3, 2021 at 7:56 PM Daniel Stenberg via curl-library

Post by Daniel Stenberg via curl-library
Ah, yes that looks interesting - especially since it fixes the problem for
you! Are you able to make a pull-request out of that and submit, or would you
like me to do it for you? Thanks!

I'm curious to know if this was followed up on? R users have been
reporting random HTTP2 framing layer errors for multiplexed
connections to google servers/apis for a long time, but I have never
succeeded to narrow down the exact problem.
-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquet

[Daniel Stenberg via curl-library]

I'm curious to know if this was followed up on? R users have been reporting
random HTTP2 framing layer errors for multiplexed connections to google
servers/apis for a long time, but I have never succeeded to narrow down the
exact problem.

https://github.com/curl/curl/pull/7192

Merged two days ago as commit a0709f99513