Deprecated: Function get_magic_quotes_gpc() is deprecated in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 99

Deprecated: The each() function is deprecated. This message will be suppressed on further calls in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 619

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1169

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176

Warning: Cannot modify header information - headers already sent by (output started at /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php:99) in /hermes/walnacweb04/walnacweb04ab/b2791/pow.jasaeld/htdocs/De1337/nothing/index.php on line 1176
8000 Process stuck on http/2 multiplex negotiate after previous request timeout · Issue #18177 · curl/curl · GitHub
Nothing Special   »   [go: up one dir, main page]

Skip to content

Process stuck on http/2 multiplex negotiate after previous request timeout #18177

@IoannisGS

Description

@IoannisGS

I did this

Hello,
We run into a very strange race condition after upgrading curl from version 8.12.1 to version 8.13.0. We tested even by building the library with the latest commits and the behaviour remains the same. It seems that it makes the curl library to wait forever a multiplex negotiation.

The following test is done with curl 8.15.0 with these curl settings:

  • CURLOPT_HTTP_VERSION : CURL_HTTP_VERSION_2_PRIOR_KNOWLEDGE
  • CURLOPT_PIPEWAIT : 1
  • CURLOPT_PROTOCOLS : CURLPROTO_HTTP | CURLPROTO_HTTPS
  • CURLOPT_TCP_KEEPALIVE : 1
  • CURLOPT_TIMEOUT_MS : 1
  • CURLMOPT_PIPELINING : CURLPIPE_MULTIPLEX

As our service connects to envoy on the same VM, which we know it supports http/2, we set the "CURL_HTTP_VERSION_2_PRIOR_KNOWLEDGE" header.

Because we set the "CURLOPT_TIMEOUT_MS" option there is a possibility that the request will timeout before the service responds. In that case curl with debug enabled will give us the following message:

Operation timed out after 1 milliseconds with 0 bytes received

Everything fine until now. The problem is that if the request that timeouts is the very 1st request to that service, when the next request will stuck. Below are the messages that we see from curl before the process stuck:

[x-x] [MULTI] multi_timeout() says this has expired
[1-x] [MULTI] [INIT] added to multi, mid=2, running=1, total=2
1-x] [MULTI] [INIT] multi_run_dirty
[1-x] [MULTI] [INIT] -> [SETUP] (line 2364)
[1-x] [MULTI] [SETUP] set expire[10] in 1000ns
[1-x] [MULTI] [SETUP] -> [CONNECT] (line 2380)
[1-x] [READ] client_reset, clear readers
[1-x] Connecting to hostname: 127.0.0.1
[1-x] Connecting to port: 1234
[1-x] Server upgrade does not support multiplex yet, wait
[1-x] Waiting on connection to negotiate possible multiplexing.
[1-x] [MULTI] [CONNECT] -> [PENDING] (line 2260)
[1-x] [MULTI] [PENDING] multi_run_dirty

By changing any of these curl settings to another value than the used ones, the issue goes away:

  • CURLOPT_HTTP_VERSION
  • CURLOPT_PIPEWAIT
  • CURLMOPT_PIPELINING

I checked the changes and it seems that the issue started after #16073 due to:

--- a/lib/url.c
+++ b/lib/url.c
@@ -1002,7 +1002,7 @@ static bool url_match_conn(struct connectdata *conn, void *userdata)
   if(match->may_multiplex &&
      (data->state.httpwant == CURL_HTTP_VERSION_2_0) &&
      (needle->handler->protocol & CURLPROTO_HTTP) &&
-     !conn->httpversion) {
+     !conn->httpversion_seen) {

If the 1st request succeeds, the httpversion_seen is set, so this codepath is not triggered. The connection that was created on the 1st request and it will be reused on the 2nd request.
If the 1st request fails due to timeout and it does not get a response, the httpversion_seen is not set. The previous connection is left intact, but for some reason it is not reuse on the 2nd request.

I expected the following

I would expect one of the following 2 scenarios:

  • The connection is closed after the 1st failed request and it is recreated on the 2nd one. Similar to what the code does if the connection does not use multiplex.
  • The connection can be reused on the second request, similar to the case that there are no issues.

I tested the following patch on top of commit b2e6dae and it solves the problem by closing the connection. As I am new to the curl code, I do not know if there is a better way to handle this issue or if there are any side-effects due to this change.

--- a/lib/multi.c
+++ b/lib/multi.c
@@ -596,7 +596,9 @@ static void multi_done_locked(struct connectdata *conn,
            conn->proxy_negotiate_state == GSS_AUTHRECV)
 #endif
      ) || conn->bits.close
-       || (mdctx->premature && !Curl_conn_is_multiplex(conn, FIRSTSOCKET))) {
+       || (mdctx->premature && !Curl_conn_is_multiplex(conn, FIRSTSOCKET))
+       || (mdctx->premature && Curl_conn_is_multiplex(conn, FIRSTSOCKET)
+            && !conn->httpversion_seen)) {
 #ifndef CURL_DISABLE_VERBOSE_STRINGS

curl/libcurl version

Issue started from curl 8.13.0 until the latest commit

operating system

CentOS Stream release 9
Kernel 5.14.0-596.el9.x86_64

Metadata

Metadata

Assignees

Labels

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions

    0