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

Write function callback is called twice after resume transfer and return CURL_WRITEFUNC_ERROR #13337

Closed
pkropachev opened this issue Apr 10, 2024 · 19 comments
Assignees

Comments

@pkropachev
Copy link

I did this

We have the scenario when we put the transfer on pause and resume it after a while and then stop transfer with CURL_WRITEFUNC_ERROR. For that we register CURLOPT_WRITEFUNCTION callback and pause the transfer by returning CURL_WRITEFUNC_PAUSE from this callback. After some delay we resume transfer by calling curl_easy_pause(..., CURLPAUSE_CONT). Then after our callback is called we stop transfer by returning CURL_WRITEFUNC_ERROR. In this scenario we faced with the problem that our callback is called twice after it had returned CURL_WRITEFUNC_ERROR.

We reproduced the behavior using example of code from the comment, but slightly simplify it.

#include <curl/curl.h>
#include <stdbool.h>
#include <stdio.h>
#include <unistd.h>

bool paused;
int call_counter;

static size_t http_body(void *buffer, size_t size, size_t nmemb, void *userp) {
  call_counter++;
  fprintf(stderr, "http_body called at %d time\n", call_counter);

  if (call_counter == 1) {
    paused = true;
    fprintf(stderr, "Return pause\n");
    return CURL_WRITEFUNC_PAUSE;
  }

  fprintf(stderr, "Return abort\n");
  return CURL_WRITEFUNC_ERROR;
}

int main(int argc, char **argv) {
  CURLM *curl_multi_handle;
  CURL *curl;

  const char *url = "http://httpbin.org";
  struct CURLMsg *msg;
  int running_handles;
  int msgs_left;
  call_counter = 0;
  paused = false;

  curl_global_init(CURL_GLOBAL_DEFAULT);
  curl_multi_handle = curl_multi_init();
  curl = curl_easy_init();

  curl_easy_setopt(curl, CURLOPT_URL, url);
  curl_easy_setopt(curl, CURLOPT_BUFFERSIZE, 1024);
  curl_easy_setopt(curl, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1);
  curl_easy_setopt(curl, CURLOPT_WRITEFUNCTION, http_body);
  curl_easy_setopt(curl, CURLOPT_VERBOSE, 1L);

  curl_multi_add_handle(curl_multi_handle, curl);

  curl_multi_perform(curl_multi_handle, &running_handles);

  while (running_handles > 0) {
    usleep(100 * 1000);

    /* Resume if transfer is paused */
    if (paused) {
      fprintf(stderr, "Resume transfer\n");
      curl_easy_pause(curl, CURLPAUSE_CONT);
      paused = false;
    }

    curl_multi_perform(curl_multi_handle, &running_handles);
  }

  msg = curl_multi_info_read(curl_multi_handle, &msgs_left);
  fprintf(stderr, "Connection finished: %s\n",
          curl_easy_strerror(msg->data.result));

  curl_multi_remove_handle(curl_multi_handle, curl);
  curl_easy_cleanup(curl);
  curl_multi_cleanup(curl_multi_handle);

  return 0;
}

In the result, we're observing the same behavior like in our use case.

#> ./pause-test  
* Host httpbin.org:80 was resolved.
* IPv6: (none)
* IPv4: 3.223.18.102, 3.208.234.136, 35.168.90.70, 18.210.102.60, 18.204.54.143, 34.232.61.91, 54.87.28.144, 52.203.147.106
*   Trying 3.223.18.102:80...
* Connected to httpbin.org (3.223.18.102) port 80
> GET / HTTP/1.1
Host: httpbin.org
Accept: */*

* Request completely sent off
< HTTP/1.1 200 OK
< via: proxy A
< Date: Wed, 10 Apr 2024 10:34:44 GMT
< Server: gunicorn/19.9.0
< Connection: Keep-Alive
< Content-Type: text/html; charset=utf-8
< Content-Length: 9593
< Access-Control-Allow-Origin: *
< Access-Control-Allow-Credentials: true
< 
http_body called at 1 time
Return pause
Resume transfer
http_body called at 2 time
Return abort
* Failure writing output to destination, passed 771 returned 4294967295
http_body called at 3 time                                                       <--- ?
Return abort
* Failure writing output to destination, passed 1795 returned 4294967295
http_body called at 4 time                                                       <--- ?
Return abort
* Failure writing output to destination, passed 1795 returned 4294967295
* Closing connection
Connection finished: Failed writing received data to disk/application

I expected the following

Callback should not be called after return CURL_WRITEFUNC_ERROR from it. Behavior is correct in case we don't put the transfer on pause.

Just comment the following block in the sample:

if (call_counter == 1) {
    paused = true;
    fprintf(stderr, "Return pause\n");
    return CURL_WRITEFUNC_PAUSE;
}

curl/libcurl version

curl 8.7.1
curl 8.7.0-DEV (x86_64-pc-linux-gnu) libcurl/8.7.0-DEV BoringSSL zlib/1.2.11 c-ares/1.27.0 libpsl/0.21.0 nghttp2/1.60.0 quiche/0.20.1
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTP2 HTTP3 HTTPS-proxy IPv6 Largefile libz NTLM PSL SSL threadsafe UnixSockets

operating system

Linux kwx1252784oftdls 5.13.0-52-generic #59~20.04.1-Ubuntu SMP Thu Jun 16 21:21:28 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

@icing icing self-assigned this Apr 10, 2024
icing added a commit to icing/curl that referenced this issue Apr 10, 2024
- remember error encountered in invoking write callback and
  always fail afterwards without further invokes
- check behaviour in test_02_17 with h2-pausing client
- refs curl#13337
@icing
Copy link
Contributor

icing commented Apr 10, 2024

Thanks for your excellent description. I could reproduce the problem and adapt one of our test cases to check this. Would you be able to test #13340 if this works for you as well?

@pkropachev
Copy link
Author

pkropachev commented Apr 10, 2024

Thanks @icing! Now behavior looks correct in the sample and our particular application.

But unfortunately we faced with another problem in master branch (currently we use curl_8-7-1 tag). By some reason callback is called twice after put transfer on pause and resume it.

In our traces it looks like the following for curl_8-7-1:

2024-04-10 18:28:04.059,150 [DEBUG] (transfer_handler.cpp:337) write_via_user_callback_data_callback called for request e6235717-422a-4d87-91f5-c34586cff8fe with buffer size 163
2024-04-10 18:28:04.064,465 [DEBUG] (transfer_handler.cpp:374) Pause receiving for request e6235717-422a-4d87-91f5-c34586cff8fe
2024-04-10 18:28:04.084,478 [DEBUG] (transfer_handler.cpp:355) Going to resume receiving for request e6235717-422a-4d87-91f5-c34586cff8fe
2024-04-10 18:28:04.084,647 [DEBUG] (transfer_handler.cpp:610) Resume receiving request e6235717-422a-4d87-91f5-c34586cff8fe
2024-04-10 18:28:04.084,733 [DEBUG] (transfer_handler.cpp:337) write_via_user_callback_data_callback called for request e6235717-422a-4d87-91f5-c34586cff8fe with buffer size 163
2024-04-10 18:28:04.084,831 [WARN ] (transfer_handler.cpp:368) Abort request e6235717-422a-4d87-91f5-c34586cff8fe due to Want to abort

In master branch:

2024-04-10 18:34:28.407,189 [DEBUG] (transfer_handler.cpp:337) write_via_user_callback_data_callback called for request aa74de12-667f-4fba-b7f9-f1a387bfebb7 with buffer size 163
2024-04-10 18:34:28.412,484 [DEBUG] (transfer_handler.cpp:374) Pause receiving for request aa74de12-667f-4fba-b7f9-f1a387bfebb7
2024-04-10 18:34:28.412,589 [DEBUG] (transfer_handler.cpp:337) write_via_user_callback_data_callback called for request aa74de12-667f-4fba-b7f9-f1a387bfebb7 with buffer size 163
2024-04-10 18:34:28.417,917 [DEBUG] (transfer_handler.cpp:374) Pause receiving for request aa74de12-667f-4fba-b7f9-f1a387bfebb7
2024-04-10 18:34:28.433,459 [DEBUG] (transfer_handler.cpp:355) Going to resume receiving for request aa74de12-667f-4fba-b7f9-f1a387bfebb7
2024-04-10 18:34:28.433,660 [DEBUG] (transfer_handler.cpp:610) Resume receiving request aa74de12-667f-4fba-b7f9-f1a387bfebb7
2024-04-10 18:34:28.433,741 [DEBUG] (transfer_handler.cpp:355) Going to resume receiving for request aa74de12-667f-4fba-b7f9-f1a387bfebb7
2024-04-10 18:34:28.433,806 [DEBUG] (transfer_handler.cpp:337) write_via_user_callback_data_callback called for request aa74de12-667f-4fba-b7f9-f1a387bfebb7 with buffer size 163
2024-04-10 18:34:28.433,888 [WARN ] (transfer_handler.cpp:368) Abort request aa74de12-667f-4fba-b7f9-f1a387bfebb7 due to Want to abort

Sorry for these logs. Just our application is quite complicated (it uses epoll and curl_multi_socket_action), at the moment I don't have an idea how to reproduce this problem with short sample.
By the way, after rolled back #13271 (just transfer.c) all looks correct in our application. I don't know how changes in #13271 impacted on this behavior.

@icing
Copy link
Contributor

icing commented Apr 11, 2024

@pkropachev, it is difficult to understand what the log means, not knowing your application. Can you get a stack trace of the second "pausing" call, where it comes from?

As an aside: if you need identifiers for requests in your application (unique for all in the same multi handle), there is CURLINFO_XFER_ID since curl 8.2.0. But then, you might need the uuids also for other purposes, in which case disregard this advice.

@pkropachev
Copy link
Author

pkropachev commented Apr 11, 2024

@icing, yes, sorry for that logs.
We were able to reproduce the problem that I described in my previous comment with short sample of code. This problem is specific for HTTP version 2 (all is ok for HTTP 1.1). Problem is reproduced with libcurl built from the current master branch. All is ok in case rollback #13271.

Anyway, initially filed problem is fixed for us. Thank you for that! We checked the fix for HTTP 1.1 and 2.
So, I'm not sure if we should continue investigation in scope of this issue or need to raise new one.

Let me describe details of the problem that we found in the master branch in next comment and attach a sample for reproducing.

@pkropachev
Copy link
Author

pkropachev commented Apr 11, 2024

So, we use libcurl built from the current master branch.

#include <curl/curl.h>
#include <stdbool.h>
#include <stdio.h>
#include <unistd.h>

bool paused;
int call_counter;

static size_t http_body(void *buffer, size_t size, size_t nmemb, void *userp) {
  call_counter++;
  fprintf(stderr, "http_body called at %d time. Callback call is %s expected\n",
          call_counter, !paused ? "" : "NOT");
  
  if (call_counter == 1) {
    paused = true;
    fprintf(stderr, "Return pause\n");
    return CURL_WRITEFUNC_PAUSE;
  }
  
  fprintf(stderr, "Return abort\n");
  return CURL_WRITEFUNC_ERROR;
}

int main(int argc, char **argv) {
  CURLM *curl_multi_handle;
  CURL *curl;

  const char *url = "https://httpbin.org/stream/1";
  struct CURLMsg *msg;
  int running_handles;
  int msgs_left;
  call_counter = 0;
  paused = false;

  curl_global_init(CURL_GLOBAL_DEFAULT);
  curl_multi_handle = curl_multi_init();
  curl = curl_easy_init();

  curl_easy_setopt(curl, CURLOPT_URL, url);
  curl_easy_setopt(curl, CURLOPT_BUFFERSIZE, 1024);
  curl_easy_setopt(curl, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1);
  // curl_easy_setopt(curl, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2_0);
  curl_easy_setopt(curl, CURLOPT_WRITEFUNCTION, http_body);
  curl_easy_setopt(curl, CURLOPT_VERBOSE, 1);

  curl_multi_add_handle(curl_multi_handle, curl);

  curl_multi_perform(curl_multi_handle, &running_handles);

  while (running_handles > 0) {
    usleep(100 * 1000);

    /* Resume if transfer is paused */
    if (paused) {
      fprintf(stderr, "Going to resume transfer\n");
      paused = false;
      curl_easy_pause(curl, CURLPAUSE_CONT);
      fprintf(stderr, "Resumed\n");
    }

    curl_multi_perform(curl_multi_handle, &running_handles);
  }

  msg = curl_multi_info_read(curl_multi_handle, &msgs_left);
  fprintf(stderr, "Connection finished: %s\n",
          curl_easy_strerror(msg->data.result));

  curl_multi_remove_handle(curl_multi_handle, curl);
  curl_easy_cleanup(curl);
  curl_multi_cleanup(curl_multi_handle);

  return 0;
}
  1. First test with HTTP/1.1. In the result we get the following output:
http_body called at 1 time. Callback call is  expected   <--- OK for pause
Return pause
Going to resume transfer                                         
http_body called at 2 time. Callback call is  expected   <--- OK for resume
Return abort
* Failure writing output to destination, passed 205 returned 4294967295
Resumed
http_body called at 3 time. Callback call is  expected
Return abort
* Failure writing output to destination, passed 205 returned 4294967295
* Connection #0 to host httpbin.org left intact
Connection finished: Failed writing received data to disk/application

All looks correct except the third call of callback. But this is due to the fix #13340 is not applied yet. 🙂

  1. Second test with HTTP/2.

You need to comment:

curl_easy_setopt(curl, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1);

and uncomment:

curl_easy_setopt(curl, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2_0);

In the result we get the following output:

http_body called at 1 time. Callback call is  expected            <--- OK for pause
Return pause
http_body called at 2 time. Callback call is NOT expected     <--- Why is this called again? We don't see "Going to resume transfer" before it
Return abort
* Failure writing output to destination, passed 205 returned 4294967295
http_body called at 3 time. Callback call is NOT expected
Return abort
* Failure writing output to destination, passed 205 returned 4294967295
* Connection #0 to host httpbin.org left intact
Connection finished: Failed writing received data to disk/application

We see that callback is called again immediately after return CURL_WRITEFUNC_PAUSE from it.

If we rollback #13271 and run tests again then we get correct behavior for both tests. Hope it will help.
Let me know if any additional information is required.

@icing
Copy link
Contributor

icing commented Apr 11, 2024

The log line * Failure writing output to destination, passed 205 returned 4294967295 indicates that this was running without the fix in #13340 ???

@pkropachev
Copy link
Author

pkropachev commented Apr 11, 2024

Yes, I think so. For example, if I run test with HTTP/2 and fix from #13340 then I get the following output:

http_body called at 1 time. Callback call is  expected
Return pause
http_body called at 2 time. Callback call is NOT expected     <--- This is second problem for HTTP/2 in master branch
Return abort
* client returned ERROR on write of 205 bytes
* Connection #0 to host httpbin.org left intact
Connection finished: Failed writing received data to disk/application

Test with HTTP/1.1 and fix from #13340:

http_body called at 1 time. Callback call is  expected
Return pause
Going to resume transfer
http_body called at 2 time. Callback call is  expected
Return abort
* client returned ERROR on write of 205 bytes
Resumed
* Connection #0 to host httpbin.org left intact
Connection finished: Failed writing received data to disk/application

So, the fix #13340 for initial problem works as expected.

@icing
Copy link
Contributor

icing commented Apr 11, 2024

Ok, thanks. Just wanted to be certain what I am looking at.

@pkropachev
Copy link
Author

This output in case using HTTP/2 is unexpected for us:

http_body called at 1 time. Callback call is  expected
Return pause
http_body called at 2 time. Callback call is NOT expected  <--- ?

We put transfer on pause by returning CURL_WRITEFUNC_PAUSE from callback. After that the callback is called again immediately after return CURL_WRITEFUNC_PAUSE from it.

@icing
Copy link
Contributor

icing commented Apr 11, 2024

The problem seems to be that https://httpbin.org/stream/1 delivers a 502 error with a short response content of 205 bytes. Those bytes get paused by your callback, then the transfer is done and finished and tries to get rid of the buffered data one last time.

Now, the discussion is: what should curl really do here for a PAUSED transfer that is done. It seems that earlier versions just discarded the data and did not try to flush it. Not sure myself what the correct behaviour is here.

@pkropachev
Copy link
Author

pkropachev commented Apr 11, 2024

It's interesting. I see the same behavior with HTTP/2 in case using https://curl.se.

@icing
Copy link
Contributor

icing commented Apr 11, 2024

I believe it will always happen on a PAUSE when the full response had been received. If you make a larger download, I'd expect this not to happen.

@icing
Copy link
Contributor

icing commented Apr 12, 2024

I updated #13340 to no longer "finish" transfers that have received everything but are paused by the client writing. I believe this should address your issue. Happy to get feedback.

@pkropachev
Copy link
Author

@icing, now the sample works correct for HTTP/1.1 and 2. There are not extra calls of the callback. Thank you!

I faced with problem with our application and haven't identified the root cause of the problem yet.

I use local Caddy server to download a binary file with size 10M. All looks correct in case use HTTP/2 (HTTPS). I collected "write" traces.

2024-04-13 13:18:19.232,088 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:695) Start transfer id=9b9eed01-80e9-493b-ae80-f34f437e0a68
*   Trying 10.122.9.44:443...
* Connected to 10.122.9.44 (10.122.9.44) port 443
* ALPN: curl offers h2,http/1.1
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256 / [blank] / UNDEF
* ALPN: server accepted h2
* Server certificate:
*  subject: [NONE]
*  start date: Apr 13 09:31:31 2024 GMT
*  expire date: Apr 13 21:31:31 2024 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* using HTTP/2
* [HTTP/2] [1] OPENED stream for https://10.122.9.44/f10M
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: 10.122.9.44]
* [HTTP/2] [1] [:path: /f10M]
* [HTTP/2] [1] [accept: */*]
> GET /f10M HTTP/2
Host: 10.122.9.44
Accept: */*

* Request completely sent off
* [WRITE] xfer_write_resp(len=7, eos=0) -> 0
* [WRITE] xfer_write_resp(len=3, eos=0) -> 0
< HTTP/2 200
* [WRITE] cw_out, wrote 13 header bytes -> 13
* [WRITE] download_write header(type=c, blen=13) -> 0
* [WRITE] client_write(type=c, len=13) -> 0
* [WRITE] xfer_write_resp(len=3, eos=0) -> 0
* [WRITE] xfer_write_resp(len=13, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=5, eos=0) -> 0
< accept-ranges: bytes
* [WRITE] header_collect pushed(type=1, len=22) -> 0
* [WRITE] cw_out, wrote 22 header bytes -> 22
* [WRITE] download_write header(type=4, blen=22) -> 0
* [WRITE] client_write(type=4, len=22) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=7, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=21, eos=0) -> 0
< alt-svc: h3=":443"; ma=2592000
* [WRITE] header_collect pushed(type=1, len=32) -> 0
* [WRITE] cw_out, wrote 32 header bytes -> 32
* [WRITE] download_write header(type=4, blen=32) -> 0
* [WRITE] client_write(type=4, len=32) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=4, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=13, eos=0) -> 0
< etag: "s95wxq68qv4"
* [WRITE] header_collect pushed(type=1, len=21) -> 0
* [WRITE] cw_out, wrote 21 header bytes -> 21
* [WRITE] download_write header(type=4, blen=21) -> 0
* [WRITE] client_write(type=4, len=21) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=13, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=29, eos=0) -> 0
< last-modified: Tue, 20 Feb 2024 16:10:38 GMT
* [WRITE] header_collect pushed(type=1, len=46) -> 0
* [WRITE] cw_out, wrote 46 header bytes -> 46
* [WRITE] download_write header(type=4, blen=46) -> 0
* [WRITE] client_write(type=4, len=46) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=6, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=5, eos=0) -> 0
< server: Caddy
* [WRITE] header_collect pushed(type=1, len=15) -> 0
* [WRITE] cw_out, wrote 15 header bytes -> 15
* [WRITE] download_write header(type=4, blen=15) -> 0
* [WRITE] client_write(type=4, len=15) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=14, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=8, eos=0) -> 0
< content-length: 10485760
* [WRITE] header_collect pushed(type=1, len=26) -> 0
* [WRITE] cw_out, wrote 26 header bytes -> 26
* [WRITE] download_write header(type=4, blen=26) -> 0
* [WRITE] client_write(type=4, len=26) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=4, eos=0) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
* [WRITE] xfer_write_resp(len=29, eos=0) -> 0
< date: Sat, 13 Apr 2024 10:18:19 GMT
* [WRITE] header_collect pushed(type=1, len=37) -> 0
* [WRITE] cw_out, wrote 37 header bytes -> 37
* [WRITE] download_write header(type=4, blen=37) -> 0
* [WRITE] client_write(type=4, len=37) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
<
* [WRITE] header_collect pushed(type=1, len=2) -> 0
* [WRITE] cw_out, wrote 2 header bytes -> 2
* [WRITE] download_write header(type=4, blen=2) -> 0
* [WRITE] client_write(type=4, len=2) -> 0
* [WRITE] xfer_write_resp(len=2, eos=0) -> 0
2024-04-13 13:18:19.234,128 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:357) write_via_user_callback_data_callback called for request 9b9eed01-80e9-493b-ae80-f34f437e0a68 with buffer size 5921
2024-04-13 13:18:19.234,190 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:361) Get access from curl callback 9b9eed01-80e9-493b-ae80-f34f437e0a68
* [WRITE] cw_out, wrote 5921 body bytes -> 5921
* [WRITE] download_write body(type=1, blen=5921) -> 0
* [WRITE] client_write(type=1, len=5921) -> 0
* [WRITE] xfer_write_resp(len=5921, eos=0) -> 0
2024-04-13 13:18:19.234,447 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:357) write_via_user_callback_data_callback called for request 9b9eed01-80e9-493b-ae80-f34f437e0a68 with buffer size 7116
2024-04-13 13:18:19.234,503 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:361) Get access from curl callback 9b9eed01-80e9-493b-ae80-f34f437e0a68
2024-04-13 13:18:19.234,561 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:389) Called before get result of the previous call 9b9eed01-80e9-493b-ae80-f34f437e0a68. Reminder size is 0
2024-04-13 13:18:19.234,622 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:394) Pause request 9b9eed01-80e9-493b-ae80-f34f437e0a68 due to cache size limit
* [WRITE] cw_out, wrote 7116 body bytes -> 268435457
* [WRITE] cw_out, PAUSE requested by client
* [WRITE] download_write body(type=1, blen=7116) -> 0
* [WRITE] client_write(type=1, len=7116) -> 0
* [WRITE] xfer_write_resp(len=7116, eos=0) -> 0
* [WRITE] download_write body(type=1, blen=3347) -> 0
* [WRITE] client_write(type=1, len=3347) -> 0
* [WRITE] xfer_write_resp(len=3347, eos=0) -> 0
2024-04-13 13:18:19.255,546 <7F86B884A840> [DEBUG] (transfer_handler.cpp:417) Get data receive callback result for 9b9eed01-80e9-493b-ae80-f34f437e0a68 Want to abort
2024-04-13 13:18:19.255,585 <7F86B884A840> [DEBUG] (transfer_handler.cpp:421) Get access from user callback 9b9eed01-80e9-493b-ae80-f34f437e0a68
2024-04-13 13:18:19.255,622 <7F86B884A840> [DEBUG] (transfer_handler.cpp:427) Going to resume 9b9eed01-80e9-493b-ae80-f34f437e0a68
2024-04-13 13:18:19.255,730 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:684) Resume receiving request 9b9eed01-80e9-493b-ae80-f34f437e0a68
* [WRITE] cw-out unpause
2024-04-13 13:18:19.255,788 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:357) write_via_user_callback_data_callback called for request 9b9eed01-80e9-493b-ae80-f34f437e0a68 with buffer size 10463
2024-04-13 13:18:19.255,837 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:361) Get access from curl callback 9b9eed01-80e9-493b-ae80-f34f437e0a68
2024-04-13 13:18:19.255,897 <7F8690DC4700> [WARN ] (transfer_handler.cpp:380) Abort request 9b9eed01-80e9-493b-ae80-f34f437e0a68 due to Want to abort
* [WRITE] cw_out, wrote 10463 body bytes -> 4294967295
* client returned ERROR on write of 10463 bytes
* [WRITE] download_write body(type=1, blen=9479) -> 23
* [WRITE] client_write(type=1, len=9479) -> 23
* [WRITE] xfer_write_resp(len=9479, eos=0) -> 23
* [WRITE] download_write body(type=1, blen=6905) -> 23
* [WRITE] client_write(type=1, len=6905) -> 23
* [WRITE] xfer_write_resp(len=6905, eos=0) -> 23
* HTTP/2 stream 1 was not closed cleanly: unknown (err 4294966394)
* [WRITE] cw-out done
* Connection #0 to host 10.122.9.44 left intact
2024-04-13 13:18:19.256,133 <7F8690DC4700> [DEBUG] (transfer_handler.cpp:610) Done id=9b9eed01-80e9-493b-ae80-f34f437e0a68

After abort the transfer I see [WRITE] cw-out done immediatly and transfer is finished with Stream error in the HTTP/2 framing layer result.

In case I use HTTP/1.1 (HTTP instead of HTTPS to force switch to 1.1) then I see that [WRITE] cw-out done appears after 30 seconds and trasnfer is finished with Failed writing received data to disk/application result.

2024-04-13 13:25:24.112,526 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:695) Start transfer id=3d81db38-f708-4ebb-a01e-5aec025eb7c8
*   Trying 10.122.9.44:80...
* Connected to 10.122.9.44 (10.122.9.44) port 80
> GET /f10M HTTP/1.1
Host: 10.122.9.44
Accept: */*

* Request completely sent off
< HTTP/1.1 200 OK
* [WRITE] cw_out, wrote 17 header bytes -> 17
* [WRITE] download_write header(type=c, blen=17) -> 0
* [WRITE] client_write(type=c, len=17) -> 0
< Accept-Ranges: bytes
* [WRITE] header_collect pushed(type=1, len=22) -> 0
* [WRITE] cw_out, wrote 22 header bytes -> 22
* [WRITE] download_write header(type=4, blen=22) -> 0
* [WRITE] client_write(type=4, len=22) -> 0
< Content-Length: 10485760
* [WRITE] header_collect pushed(type=1, len=26) -> 0
* [WRITE] cw_out, wrote 26 header bytes -> 26
* [WRITE] download_write header(type=4, blen=26) -> 0
* [WRITE] client_write(type=4, len=26) -> 0
< Etag: "s95wxq68qv4"
* [WRITE] header_collect pushed(type=1, len=21) -> 0
* [WRITE] cw_out, wrote 21 header bytes -> 21
* [WRITE] download_write header(type=4, blen=21) -> 0
* [WRITE] client_write(type=4, len=21) -> 0
< Last-Modified: Tue, 20 Feb 2024 16:10:38 GMT
* [WRITE] header_collect pushed(type=1, len=46) -> 0
* [WRITE] cw_out, wrote 46 header bytes -> 46
* [WRITE] download_write header(type=4, blen=46) -> 0
* [WRITE] client_write(type=4, len=46) -> 0
< Server: Caddy
* [WRITE] header_collect pushed(type=1, len=15) -> 0
* [WRITE] cw_out, wrote 15 header bytes -> 15
* [WRITE] download_write header(type=4, blen=15) -> 0
* [WRITE] client_write(type=4, len=15) -> 0
< Date: Sat, 13 Apr 2024 10:25:24 GMT
* [WRITE] header_collect pushed(type=1, len=37) -> 0
* [WRITE] cw_out, wrote 37 header bytes -> 37
* [WRITE] download_write header(type=4, blen=37) -> 0
* [WRITE] client_write(type=4, len=37) -> 0
<
* [WRITE] header_collect pushed(type=1, len=2) -> 0
* [WRITE] cw_out, wrote 2 header bytes -> 2
* [WRITE] download_write header(type=4, blen=2) -> 0
* [WRITE] client_write(type=4, len=2) -> 0
2024-04-13 13:25:24.113,186 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:357) write_via_user_callback_data_callback called for request 3d81db38-f708-4ebb-a01e-5aec025eb7c8 with buffer size 512
2024-04-13 13:25:24.113,249 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:361) Get access from curl callback 3d81db38-f708-4ebb-a01e-5aec025eb7c8
* [WRITE] cw_out, wrote 512 body bytes -> 512
* [WRITE] download_write body(type=1, blen=512) -> 0
* [WRITE] client_write(type=1, len=512) -> 0
* [WRITE] xfer_write_resp(len=698, eos=0) -> 0
2024-04-13 13:25:24.113,425 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:357) write_via_user_callback_data_callback called for request 3d81db38-f708-4ebb-a01e-5aec025eb7c8 with buffer size 16384
2024-04-13 13:25:24.113,489 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:361) Get access from curl callback 3d81db38-f708-4ebb-a01e-5aec025eb7c8
2024-04-13 13:25:24.113,546 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:389) Called before get result of the previous call 3d81db38-f708-4ebb-a01e-5aec025eb7c8. Reminder size is 0
2024-04-13 13:25:24.113,592 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:394) Pause request 3d81db38-f708-4ebb-a01e-5aec025eb7c8 due to cache size limit
* [WRITE] cw_out, wrote 16384 body bytes -> 268435457
* [WRITE] cw_out, PAUSE requested by client
* [WRITE] download_write body(type=1, blen=16384) -> 0
* [WRITE] client_write(type=1, len=16384) -> 0
* [WRITE] xfer_write_resp(len=16384, eos=0) -> 0
2024-04-13 13:25:24.134,453 <7F6B75F6D840> [DEBUG] (transfer_handler.cpp:417) Get data receive callback result for 3d81db38-f708-4ebb-a01e-5aec025eb7c8 Want to abort
2024-04-13 13:25:24.134,489 <7F6B75F6D840> [DEBUG] (transfer_handler.cpp:421) Get access from user callback 3d81db38-f708-4ebb-a01e-5aec025eb7c8
2024-04-13 13:25:24.134,525 <7F6B75F6D840> [DEBUG] (transfer_handler.cpp:427) Going to resume 3d81db38-f708-4ebb-a01e-5aec025eb7c8
2024-04-13 13:25:24.134,614 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:684) Resume receiving request 3d81db38-f708-4ebb-a01e-5aec025eb7c8
* [WRITE] cw-out unpause
2024-04-13 13:25:24.134,663 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:357) write_via_user_callback_data_callback called for request 3d81db38-f708-4ebb-a01e-5aec025eb7c8 with buffer size 16384
2024-04-13 13:25:24.134,699 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:361) Get access from curl callback 3d81db38-f708-4ebb-a01e-5aec025eb7c8
2024-04-13 13:25:24.134,741 <7F6B4E475700> [WARN ] (transfer_handler.cpp:380) Abort request 3d81db38-f708-4ebb-a01e-5aec025eb7c8 due to Want to abort
* [WRITE] cw_out, wrote 16384 body bytes -> 4294967295
* client returned ERROR on write of 16384 bytes

<--- By some reason gets stuck 30 seconds here --->

* [WRITE] download_write body(type=1, blen=16384) -> 23
* [WRITE] client_write(type=1, len=16384) -> 23
* [WRITE] xfer_write_resp(len=16384, eos=0) -> 23
* [WRITE] cw-out done
* Closing connection
2024-04-13 13:25:54.113,088 <7F6B4E475700> [DEBUG] (transfer_handler.cpp:610) Done id=3d81db38-f708-4ebb-a01e-5aec025eb7c8

At the moment I don't have any ideas why it happens. So, I need a bit more time to understand why it's happening.

Could you please share if there is some place in libcurl that potentially can "return" cw-out done after a while due to waiting something?

@icing
Copy link
Contributor

icing commented Apr 15, 2024

Interesting application you have there. I updated #13340 again to take care of the situation where curl_easy_pause() errors (due to client write failures), but the application keeps the transfer going.

Now, the actual unpaused writes happen during "normal" transfer processing and lead to a failed transfer as they should. Thus, curl_easy_pause() no longer reports the error from the write callback.

icing added a commit to icing/curl that referenced this issue Apr 15, 2024
- remember error encountered in invoking write callback and
  always fail afterwards without further invokes
- check behaviour in test_02_17 with h2-pausing client
- refs curl#13337
@icing
Copy link
Contributor

icing commented Apr 16, 2024

@pkropachev it would be nice to know how the updated PR works for you. Thanks.

@pkropachev
Copy link
Author

@icing, sorry for the delay with reply. We'll test it today and give feedback. Thanks!

@pkropachev
Copy link
Author

pkropachev commented Apr 16, 2024

@icing, I can confirm now it works great for the sample and our application.
We checked with public servers with HTTP/1.1 and HTTP/2 versions. Also all is correct with local servers Caddy and Nginx with HTTP/1.1, HTTP/2 and HTTP/3.
Thanks a lot!

@icing
Copy link
Contributor

icing commented Apr 16, 2024

Thanks for confirming and the help in providing sample code!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

3 participants