Navigation Menu

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HTTP/2 stream is not reset after timeout #2882

Closed
mkauf opened this issue Aug 14, 2018 · 12 comments
Closed

HTTP/2 stream is not reset after timeout #2882

mkauf opened this issue Aug 14, 2018 · 12 comments
Labels

Comments

@mkauf
Copy link
Contributor

mkauf commented Aug 14, 2018

I did this

The following test program creates two transfers:

  • an HTTP/2 transfer, with a timeout of 10 seconds
  • an HTTP/1.1 transfer, without timeout

After the timeout of 10 seconds, the first transfer (HTTP/2) should stop and the HTTP/2 stream should be reset. libcurl does not deliver the received data anymore to the application, but libcurl does not reset the HTTP/2 stream and the data is still transferred over the wire. This can be checked with Wireshark (hints). As long as the second transfer (HTTP/1.1) is active, the HTTP/2 transfer is not really stopped.

The URL points to a PHP script that sends data in an infinite loop:

<?php

while (1) {
    echo str_repeat("a", 4096);
    echo "\n";
    echo "time: " . time();
    echo "\n";
    flush();
    ob_flush();
    sleep(1);
}

Test program:

#include <stdio.h>
#include <string.h>

/* somewhat unix-specific */
#include <sys/time.h>
#include <unistd.h>

/* curl stuff */
#include <curl/curl.h>

#ifdef _WIN32
#define WAITMS(x) Sleep(x)
#else
/* Portable sleep for platforms other than Windows. */
#define WAITMS(x)                               \
  struct timeval wait = { 0, (x) * 1000 };      \
  (void)select(0, NULL, NULL, NULL, &wait);
#endif

/*
 * Simply download a HTTP file.
 */
int main(void)
{
  CURL *http_handle_a;
  CURL *http_handle_b;
  CURLM *multi_handle;

  int still_running; /* keep number of running handles */
  int repeats = 0;

  curl_global_init(CURL_GLOBAL_DEFAULT);

  http_handle_a = curl_easy_init();
  http_handle_b = curl_easy_init();

  curl_easy_setopt(http_handle_a, CURLOPT_URL, "https://localhost/test.php");
  curl_easy_setopt(http_handle_b, CURLOPT_URL, "https://localhost/test.php");

  curl_easy_setopt(http_handle_a, CURLOPT_VERBOSE, 1L);
  curl_easy_setopt(http_handle_b, CURLOPT_VERBOSE, 1L);

  curl_easy_setopt(http_handle_a, CURLOPT_SSL_VERIFYPEER, 0L);
  curl_easy_setopt(http_handle_b, CURLOPT_SSL_VERIFYPEER, 0L);

  curl_easy_setopt(http_handle_a, CURLOPT_SSL_VERIFYHOST, 0L);
  curl_easy_setopt(http_handle_b, CURLOPT_SSL_VERIFYHOST, 0L);

  curl_easy_setopt(http_handle_a, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2TLS);
  //curl_easy_setopt(http_handle_b, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2TLS);

  curl_easy_setopt(http_handle_a, CURLOPT_PIPEWAIT, 1L);
  //curl_easy_setopt(http_handle_b, CURLOPT_PIPEWAIT, 1L);

  curl_easy_setopt(http_handle_a, CURLOPT_TIMEOUT, 10L);

  /* init a multi stack */
  multi_handle = curl_multi_init();

  curl_multi_setopt(multi_handle, CURLMOPT_PIPELINING, CURLPIPE_MULTIPLEX);

  /* add the individual transfers */
  curl_multi_add_handle(multi_handle, http_handle_a);
  curl_multi_add_handle(multi_handle, http_handle_b);

  /* we start some action by calling perform right away */
  curl_multi_perform(multi_handle, &still_running);

  do {
    CURLMcode mc; /* curl_multi_wait() return code */
    int numfds;

    /* wait for activity, timeout or "nothing" */
    mc = curl_multi_wait(multi_handle, NULL, 0, 1000, &numfds);

    if(mc != CURLM_OK) {
      fprintf(stderr, "curl_multi_wait() failed, code %d.\n", mc);
      break;
    }

    /* 'numfds' being zero means either a timeout or no file descriptors to
       wait for. Try timeout on first occurrence, then assume no file
       descriptors and no file descriptors to wait for means wait for 100
       milliseconds. */

    if(!numfds) {
      repeats++; /* count number of repeated zero numfds */
      if(repeats > 1) {
        WAITMS(100); /* sleep 100 milliseconds */
      }
    }
    else
      repeats = 0;

    curl_multi_perform(multi_handle, &still_running);
  } while(still_running);

  curl_multi_remove_handle(multi_handle, http_handle_a);
  curl_multi_remove_handle(multi_handle, http_handle_b);

  curl_easy_cleanup(http_handle_a);
  curl_easy_cleanup(http_handle_b);

  curl_multi_cleanup(multi_handle);

  curl_global_cleanup();

  return 0;
}

I expected the following

When the HTTP/2 transfer timeouts, the HTTP/2 stream should be reset.

curl/libcurl version

curl 7.61.1-DEV (x86_64-pc-linux-gnu) libcurl/7.61.1-DEV OpenSSL/1.1.0h zlib/1.2.11 nghttp2/1.32.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy

operating system

Linux

@mkauf mkauf added the HTTP/2 label Aug 14, 2018
@bagder
Copy link
Member

bagder commented Aug 14, 2018

I'm afraid this doesn't seem to reproduce that easily for me.

In my log output I get (after ~10 seconds):

* Operation timed out after 10101 milliseconds with 0 bytes received
* Kill stream: Disconnected with pending data
* multi_done
* Connection #0 to host daniel.haxx.se left intact
* Expire cleared

@bagder
Copy link
Member

bagder commented Aug 14, 2018

@mkauf, can you try to set a break-point in Curl_http2_done and see if nghttp2_submit_rst_stream() gets called in there when the http2 transfer is to be ended?

@mkauf
Copy link
Contributor Author

mkauf commented Aug 15, 2018

@bagder Yes, nghttp2_submit_rst_stream() gets called in Curl_http2_done. But nghttp2_session_send() is not called afterwards. This probably must be called to send the "stream reset" over the wire.

It works for me when I add a call to nghttp2_session_send() after nghttp2_submit_rst_stream(). But probably this is not the "full bugfix". If the output buffer is full, then nghttp2_session_send() needs to be called again later. But where?

(Maybe you can reproduce the bug if you increase the buffer size in the PHP script. PHP does buffering, Apache too... so sending more bytes could help)

@bagder
Copy link
Member

bagder commented Aug 15, 2018

Thanks, now I understand it much better!

@bagder
Copy link
Member

bagder commented Aug 15, 2018

I think calling h2_session_send() there is the first step and will fix the common case. We should do this first I think.

I believe the larger issue is harder and might take something like #1641 to get fixed properly, since we will need to monitor this connection after the transfer is complete on it and it is returned to the connection pool, in an edge case to make sure the RST_STREAM is ultimately actually sent off!

@mkauf
Copy link
Contributor Author

mkauf commented Aug 15, 2018

h2_session_send() should not be called for HTTP/1.x connections. This works:

diff --git a/lib/http2.c b/lib/http2.c
index da001dfd0..327bb9b60 100644
--- a/lib/http2.c
+++ b/lib/http2.c
@@ -1126,8 +1126,10 @@ void Curl_http2_done(struct connectdata *conn, bool premature)
 
   if(premature) {
     /* RST_STREAM */
-    nghttp2_submit_rst_stream(httpc->h2, NGHTTP2_FLAG_NONE, http->stream_id,
-                              NGHTTP2_STREAM_CLOSED);
+    if(nghttp2_submit_rst_stream(httpc->h2, NGHTTP2_FLAG_NONE,
+        http->stream_id, NGHTTP2_STREAM_CLOSED) == 0) {
+      nghttp2_session_send(httpc->h2);
+    }
     if(http->stream_id == httpc->pause_stream_id) {
       infof(data, "stopped the pause stream!\n");
       httpc->pause_stream_id = 0;

@bagder
Copy link
Member

bagder commented Aug 15, 2018

h2_session_send() should not be called for HTTP/1.x connections

Huh? This is a http2 connection so I don't understand that comment.

We use h2_session_send() in most places in http2.c instead of directly calling nghttp2_session_send() so that it can detect and handle priority changes.

@bagder
Copy link
Member

bagder commented Aug 15, 2018

And by all means, make a PR out of it! 👍

@mkauf
Copy link
Contributor Author

mkauf commented Aug 16, 2018

Huh? This is a http2 connection so I don't understand that comment.

Curl_http2_done() is also called for HTTP 1.x connections. Weird things happen if nghttp2_session_send() is called for such connections.

@bagder
Copy link
Member

bagder commented Aug 16, 2018

Curl_http2_done() is also called for HTTP 1.x connections

Oh, right. So I think it should better bail out early if so:

diff --git a/lib/http2.c b/lib/http2.c
index e9ec73a6d..1031d0627 100644
--- a/lib/http2.c
+++ b/lib/http2.c
@@ -1144,10 +1144,13 @@ void Curl_http2_done(struct connectdata *conn, bool premature)
 {
   struct Curl_easy *data = conn->data;
   struct HTTP *http = data->req.protop;
   struct http_conn *httpc = &conn->proto.httpc;
 
+  if(!httpc->h2) /* not HTTP/2 ? */
+    return;
+
   if(data->state.drain)
     drained_transfer(data, httpc);
 
   if(http->header_recvbuf) {
     Curl_add_buffer_free(http->header_recvbuf);

bagder added a commit that referenced this issue Aug 16, 2018
If this is the last stream on this connection, the RST_STREAM might not
get pushed to the wire otherwise.

Fixes #2882
Researched-by: Michael Kaufmann
@bagder
Copy link
Member

bagder commented Aug 16, 2018

I hope you don't mind, but I created #2887 to show my take. What do you say?

@mkauf
Copy link
Contributor Author

mkauf commented Aug 17, 2018

Thanks, I left comments in the PR.

bagder added a commit that referenced this issue Aug 17, 2018
If this is the last stream on this connection, the RST_STREAM might not
get pushed to the wire otherwise.

Fixes #2882
Researched-by: Michael Kaufmann
@bagder bagder closed this as completed in c7ea4dd Aug 17, 2018
xquery pushed a commit to xquery/curl that referenced this issue Sep 3, 2018
If this is the last stream on this connection, the RST_STREAM might not
get pushed to the wire otherwise.

Fixes curl#2882
Closes curl#2887
Researched-by: Michael Kaufmann
falconindy pushed a commit to falconindy/curl that referenced this issue Sep 10, 2018
If this is the last stream on this connection, the RST_STREAM might not
get pushed to the wire otherwise.

Fixes curl#2882
Closes curl#2887
Researched-by: Michael Kaufmann
@lock lock bot locked as resolved and limited conversation to collaborators Nov 15, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Development

No branches or pull requests

2 participants