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

libcurl: unpausing is broken for http2 requests in 7.84 #9180

Closed
tilicho opened this issue Jul 19, 2022 · 3 comments
Closed

libcurl: unpausing is broken for http2 requests in 7.84 #9180

tilicho opened this issue Jul 19, 2022 · 3 comments
Assignees

Comments

@tilicho
Copy link

@tilicho tilicho commented Jul 19, 2022

I did this

  1. initialize http2 request with custom write callbacks for headers and body data from server (using CURLOPT_HEADERFUNCTION, CURLOPT_WRITEFUNCTION). wait for http2 request to be sent to server.
  2. pause request by returning CURL_WRITEFUNC_PAUSE from write callbacks.
  3. continue processing requests next 10-20 seconds. http2 response arrives from server for paused request during this time.
  4. unpause request using curl_easy_pause.
  5. wait for write callbacks to be called with headers and data from server.

see test example below

I expected the following

  1. I expected what curl_easy_pause will return success in step 4. It returns CURLE_BAD_FUNCTION_ARGUMENT (43).
  2. I expected that after unpausing request write callbacks for response headers and body will be called. But I didn't get headers and data.

curl/libcurl version

7.84.0
In previous version there is no problem with resuming http2 requests.

operating system

all


test example

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <errno.h>
#include <sys/time.h>
#include <unistd.h>
#include <curl/curl.h>
#include <assert.h>

struct transfer {
  CURL *easy;
  int paused;
  int writed_data;
  int writed_headers;
};

size_t write_header(void *ptr, size_t size, size_t nmemb, void *userdata)
{
    struct transfer* tr;

    tr = (struct transfer*)(userdata);
    
    // report that request was paused
    if (tr->paused)
    {
        fprintf(stderr, ">> write_header %li paused \n", nmemb);
        return CURL_WRITEFUNC_PAUSE;
    }

    fprintf(stderr, ">> write_header %li resumed \n", nmemb);
    tr->writed_headers += size * nmemb;
    return size * nmemb;
}

size_t write_data(void *ptr, size_t size, size_t nmemb, void* userdata)
{
    struct transfer* tr;

    tr = (struct transfer*)(userdata);

    // report that request was paused
    if (tr->paused)
    {
        fprintf(stderr, ">> write_data %li paused \n", nmemb);
        return CURL_WRITEFUNC_PAUSE;
    }

    fprintf(stderr, ">> write_data %li resumed! \n", nmemb);
    tr->writed_data += size * nmemb;
    return size * nmemb;
}

static void setup(struct transfer *t)
{
  CURL *hnd;

  hnd = t->easy = curl_easy_init();

  t->paused = 1;
  t->writed_data = 0;
  t->writed_headers = 0;

  // use custom callbacks for response headers and data
  curl_easy_setopt(hnd, CURLOPT_HEADERFUNCTION, &write_header);
  curl_easy_setopt(hnd, CURLOPT_WRITEHEADER, t);

  curl_easy_setopt(hnd, CURLOPT_WRITEFUNCTION, &write_data);
  curl_easy_setopt(hnd, CURLOPT_WRITEDATA, t);

  // pass any server url that supports http2 and returns response with body
  curl_easy_setopt(hnd, CURLOPT_URL, "https://www.nghttp2.org/"); 
  curl_easy_setopt(hnd, CURLOPT_VERBOSE, 1L);

  curl_easy_setopt(hnd, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2_0);

  // skip verification for test
  curl_easy_setopt(hnd, CURLOPT_SSL_VERIFYPEER, 0L);
  curl_easy_setopt(hnd, CURLOPT_SSL_VERIFYHOST, 0L);
}

static void resume(struct transfer *t)
{
  CURL *hnd;
  int resResume;

  hnd = t->easy;
  t->paused = 0;
  resResume = curl_easy_pause(hnd, 0L);
  fprintf(stderr, "curl_easy_pause result %i\n", resResume);
}

int main(int argc, char **argv)
{
  struct transfer trans;
  CURLM *multi_handle;
  int still_running = 0; 
  int poll_counter = 0;

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

  setup(&trans);

  curl_multi_add_handle(multi_handle, trans.easy);

  do {
    CURLMcode mc = curl_multi_perform(multi_handle, &still_running);

    if(still_running)
      /* wait for activity, timeout or "nothing" */
      mc = curl_multi_poll(multi_handle, NULL, 0, 1000, NULL);

    ++poll_counter;

    if(mc)
      break;

    // after few multi poll calls resume request
    if (poll_counter == 10)
    {
        fprintf(stderr, "Resume transfers!\n");
        resume(&trans);
    }

  } while(still_running);

  // trace received headers and body bytes
  fprintf(stderr, "writed headers %i\n", trans.writed_headers);
  fprintf(stderr, "writed data size %i\n", trans.writed_data);
  
  // assert that we received some headers and body
  assert(trans.writed_headers > 0);
  assert(trans.writed_data > 0);
  
  curl_multi_remove_handle(multi_handle, trans.easy);
  curl_easy_cleanup(trans.easy);

  curl_multi_cleanup(multi_handle);

  return 0;
}

Possible breaking commit

d1e4a67

Possible fix

I think it should be near this line:

return pausewrite(data, CLIENTWRITE_HEADER, optr, olen);

static CURLcode chop_write(struct Curl_easy *data,
                           int type,
                           char *optr,
                           size_t olen)
struct http_conn *httpc = &data->conn->proto.httpc;
...

  if(CURL_WRITEFUNC_PAUSE == wrote)
  {
    /* here we pass in the HEADER bit only since if this was body as well
       then it was passed already and clearly that didn't trigger the
       pause, so this is saved for later with the HEADER bit only */
    
    //at least for http2 transfers we should pass original type (which can be CLIENTWRITE_STATUS and http2 status should be processed not as normal CLIENTWRITE_HEADER)
    if (httpc->h2)
    {
       infof(data, "pausewrite fix for http2 headers of type %d", type);
       return pausewrite(data, type, optr, olen);
    }
    
    return pausewrite(data, CLIENTWRITE_HEADER, optr, olen);
  }
@bagder bagder added the HTTP/2 label Jul 19, 2022
@bagder bagder self-assigned this Jul 19, 2022
@bagder
Copy link
Member

@bagder bagder commented Jul 19, 2022

What is the output when you run that test code?

When I run with curl from git (debug-enabled) using nghttp2 1.47.0 on Linux, it shows:

* STATE: INIT => CONNECT handle 0x561ad74218c8; line 1837 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x561ad74218c8; line 1883 (connection #0)
Resume transfers!
* pause: no change, early return
curl_easy_pause result 0
* family0 == v6, family1 == v4
*   Trying 2400:8902::f03c:91ff:fe69:a454:443...
* STATE: RESOLVING => CONNECTING handle 0x561ad74218c8; line 1967 (connection #0)
*   Trying 139.162.123.134:443...
* Connected to www.nghttp2.org (2400:8902::f03c:91ff:fe69:a454) port 443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x561ad74218c8; line 2030 (connection #0)
* ALPN: offers h2
* ALPN: offers http/1.1
* Didn't find Session ID in cache for host HTTPS://www.nghttp2.org:443
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x561ad74218c8; line 2050 (connection #0)
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=nghttp2.org
*  start date: Jun 20 00:00:19 2022 GMT
*  expire date: Sep 18 00:00:18 2022 GMT
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* STATE: PROTOCONNECTING => DO handle 0x561ad74218c8; line 2069 (connection #0)
* Using HTTP2, server supports multiplexing
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* h2h3 [:method: GET]
* h2h3 [:path: /]
* h2h3 [:scheme: https]
* h2h3 [:authority: www.nghttp2.org]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x561ad74218c8)
> GET / HTTP/2
Host: www.nghttp2.org
accept: */*

* STATE: DO => DID handle 0x561ad74218c8; line 2149 (connection #0)
* multi changed, check CONNECT_PEND queue
* STATE: DID => PERFORMING handle 0x561ad74218c8; line 2268 (connection #0)
* Didn't find Session ID in cache for host HTTPS://www.nghttp2.org:443
* Added Session ID to cache for HTTPS://www.nghttp2.org:443 [server]
* Found Session ID in cache for host HTTPS://www.nghttp2.org:443
* old SSL session ID is stale, removing
* Added Session ID to cache for HTTPS://www.nghttp2.org:443 [server]
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
>> write_header 13 resumed 
< date: Tue, 19 Jul 2022 14:17:37 GMT
>> write_header 37 resumed 
< content-type: text/html
>> write_header 25 resumed 
< last-modified: Tue, 05 Jul 2022 09:43:52 GMT
>> write_header 46 resumed 
< etag: "62c407d8-18b4"
>> write_header 23 resumed 
< accept-ranges: bytes
>> write_header 22 resumed 
< content-length: 6324
>> write_header 22 resumed 
< x-backend-header-rtt: 0.003492
>> write_header 32 resumed 
< strict-transport-security: max-age=31536000
>> write_header 45 resumed 
< server: nghttpx
>> write_header 17 resumed 
< alt-svc: h3=":443"; ma=3600, h3-29=":443"; ma=3600
>> write_header 52 resumed 
< via: 2 nghttpx
>> write_header 16 resumed 
< x-frame-options: SAMEORIGIN
>> write_header 29 resumed 
< x-xss-protection: 1; mode=block
>> write_header 33 resumed 
< x-content-type-options: nosniff
>> write_header 33 resumed 
>> write_header 2 resumed 
< 
>> write_data 6324 resumed! 
* nread == 0, stream closed, bailing
* STATE: PERFORMING => DONE handle 0x561ad74218c8; line 2467 (connection #0)
* multi_done: status: 0 prem: 0 done: 0
* Connection #0 to host www.nghttp2.org left intact
* Expire cleared (transfer 0x561ad74218c8)
writed headers 447
writed data size 6324

@tilicho
Copy link
Author

@tilicho tilicho commented Jul 19, 2022

I think that it could be because request resumes without being paused in callback.

Resume transfers!
* pause: no change, early return

You could run example few times, or change wait timeout (set max poll counter to 20: if (poll_counter == 20)).

In my case (nghttp2 1.47 also, system is linux/macos) output is:

*   Trying 139.162.123.134:443...
* Connected to www.nghttp2.org (139.162.123.134) port 443 (#0)
* ALPN: offers h2
* ALPN: offers http/1.1
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=nghttp2.org
*  start date: Jun 20 00:00:19 2022 GMT
*  expire date: Sep 18 00:00:18 2022 GMT
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multiplexing
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* h2h3 [:method: GET]
* h2h3 [:path: /]
* h2h3 [:scheme: https]
* h2h3 [:authority: www.nghttp2.org]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x13000a808)
> GET / HTTP/2
Host: www.nghttp2.org
accept: */*

* old SSL session ID is stale, removing
< HTTP/2 200 
>> write_header 13 paused 
< date: Tue, 19 Jul 2022 15:09:47 GMT
< content-type: text/html
< last-modified: Tue, 05 Jul 2022 09:43:52 GMT
< etag: "62c407d8-18b4"
< accept-ranges: bytes
< content-length: 6324
< x-backend-header-rtt: 0.002773
< strict-transport-security: max-age=31536000
< server: nghttpx
< alt-svc: h3=":443"; ma=3600, h3-29=":443"; ma=3600
< via: 2 nghttpx
< x-frame-options: SAMEORIGIN
< x-xss-protection: 1; mode=block
< x-content-type-options: nosniff
< 
Resume transfers!
curl_easy_pause result 43
* Connection #0 to host www.nghttp2.org left intact
writed headers 0
writed data size 0
Assertion failed: (trans.writed_data > 0), function main, file test.c, line 125.

more stable example would be:

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <errno.h>
#include <sys/time.h>
#include <unistd.h>
#include <curl/curl.h>
#include <assert.h>

struct transfer {
  CURL *easy;
  int paused;
  int header_callback_called;
  int writed_data;
  int writed_headers;
};

size_t write_header(void *ptr, size_t size, size_t nmemb, void *userdata)
{
    struct transfer* tr;

    tr = (struct transfer*)(userdata);
    tr->header_callback_called = 1;
    if (tr->paused)
    {
        fprintf(stderr, ">> write_header %li paused \n", nmemb);
        return CURL_WRITEFUNC_PAUSE;
    }

    fprintf(stderr, ">> write_header %li resumed \n", nmemb);
    tr->writed_headers += size * nmemb;
    return size * nmemb;
}

size_t write_data(void *ptr, size_t size, size_t nmemb, void* userdata)
{
    struct transfer* tr;

    tr = (struct transfer*)(userdata);

    if (tr->paused)
    {
        fprintf(stderr, ">> write_data %li paused \n", nmemb);
        return CURL_WRITEFUNC_PAUSE;
    }

    fprintf(stderr, ">> write_data %li resumed! \n", nmemb);
    tr->writed_data += size * nmemb;
    return size * nmemb;
}

static void setup(struct transfer *t)
{
  CURL *hnd;

  hnd = t->easy = curl_easy_init();

  t->paused = 1;
  t->writed_data = 0;
  t->writed_headers = 0;
  t->header_callback_called = 0;

  curl_easy_setopt(hnd, CURLOPT_HEADERFUNCTION, &write_header);
  curl_easy_setopt(hnd, CURLOPT_WRITEHEADER, t);

  curl_easy_setopt(hnd, CURLOPT_WRITEFUNCTION, &write_data);
  curl_easy_setopt(hnd, CURLOPT_WRITEDATA, t);

  curl_easy_setopt(hnd, CURLOPT_URL, "https://www.nghttp2.org/"); 
  curl_easy_setopt(hnd, CURLOPT_VERBOSE, 1L);

  /* HTTP/2 please */
  curl_easy_setopt(hnd, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2_0);

  /* skip verification during debugging */
  curl_easy_setopt(hnd, CURLOPT_SSL_VERIFYPEER, 0L);
  curl_easy_setopt(hnd, CURLOPT_SSL_VERIFYHOST, 0L);
}

static void resume(struct transfer *t)
{
  CURL *hnd;
  int resResume;

  hnd = t->easy;
  t->paused = 0;
  resResume = curl_easy_pause(hnd, 0L);
  fprintf(stderr, "curl_easy_pause result %i\n", resResume);
}

int main(int argc, char **argv)
{
  struct transfer trans;
  CURLM *multi_handle;
  int still_running = 0; /* keep number of running handles */
  int poll_counter = 0;

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

  setup(&trans);

  /* add the individual transfer */
  curl_multi_add_handle(multi_handle, trans.easy);

  do {
    CURLMcode mc = curl_multi_perform(multi_handle, &still_running);

    if(still_running)
      /* wait for activity, timeout or "nothing" */
      mc = curl_multi_poll(multi_handle, NULL, 0, 1000, NULL);

    ++poll_counter;

    if(mc)
      break;

    //resume transfer after header callback called
    if (trans.header_callback_called && trans.paused)
    {
        fprintf(stderr, "Resume transfers after write header callback!\n");
        resume(&trans);
    }

  } while(still_running);

  fprintf(stderr, "writed headers %i\n", trans.writed_headers);
  fprintf(stderr, "writed data size %i\n", trans.writed_data);
  assert(trans.writed_data > 0);
  assert(trans.writed_headers > 0);
  curl_multi_remove_handle(multi_handle, trans.easy);
  curl_easy_cleanup(trans.easy);

  curl_multi_cleanup(multi_handle);

  return 0;
}

@bagder
Copy link
Member

@bagder bagder commented Jul 19, 2022

Thanks, that reproduced for me too now.

bagder added a commit that referenced this issue Jul 19, 2022
Regression since d1e4a67

Reported-by: Sergey Ogryzkov
Fixes #9180
@bagder bagder closed this as completed in 6f03710 Jul 19, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants