Comments (19)
icing
commented on June 1, 2024
2
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.
from curl.
icing
commented on June 1, 2024
1
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?
from curl.
pkropachev
commented on June 1, 2024
1
@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.
from curl.
icing
commented on June 1, 2024
1
Ok, thanks. Just wanted to be certain what I am looking at.
from curl.
icing
commented on June 1, 2024
1
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.
from curl.
pkropachev
commented on June 1, 2024
1
@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!
from curl.
pkropachev
commented on June 1, 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.
from curl.
icing
commented on June 1, 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.
from curl.
pkropachev
commented on June 1, 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;
}- 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. 🙂
- 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.
from curl.
icing
commented on June 1, 2024
The log line * Failure writing output to destination, passed 205 returned 4294967295 indicates that this was running without the fix in #13340 ???
from curl.
pkropachev
commented on June 1, 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.
from curl.
pkropachev
commented on June 1, 2024
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.
from curl.
icing
commented on June 1, 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.
from curl.
pkropachev
commented on June 1, 2024
It's interesting. I see the same behavior with HTTP/2 in case using https://curl.se.
from curl.
icing
commented on June 1, 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.
from curl.
pkropachev
commented on June 1, 2024
@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?
from curl.
icing
commented on June 1, 2024
@pkropachev it would be nice to know how the updated PR works for you. Thanks.
from curl.
pkropachev
commented on June 1, 2024
@icing, sorry for the delay with reply. We'll test it today and give feedback. Thanks!
from curl.
icing
commented on June 1, 2024
Thanks for confirming and the help in providing sample code!
from curl.
Related Issues (20)
- Change in behaviour for duplicate "Transfer-Encoding = chunked" headers HOT 3
- Please update tiny-curl HOT 1
- SOCKS problem with 8.7.0+ HOT 22
- test 345 fails on AppVeyor HOT 2
- Unable to upload file with curl when --limit-rate is set to specific value HOT 3
- GitHub actions major outage/problem HOT 2
- `git clone` hangs with curl-8.7.1 HOT 7
- wolfSSL HTTP/3 peer verification is lacking HOT 4
- Ambiguous error message when decompressing brotli stream HOT 2
- CURL_VERSION_GSSAPI is not display on curl tool. HOT 4
- Bug in Debian (curl-8.7.1) leads to Failed writing received data to disk/application HOT 10
- Error 451 when transfering certain files using FTPS\TLS1.3 HOT 1
- Fail during configure if perl is missing but required HOT 5
- Windows DNS resolution: Curl crash when GetAddrInfoExW callback invoked on shutdown HOT 7
- CURLOPT_SSLVERSION: C++20 deprecation warning when values of two enums are combined HOT 1
- Sign the un-preprocessed `git archive` .tar.gz
- CMake: Fail to looking for symbols in BoringSSL HOT 6
- Compiling "threaded-ssl.c" with PThreads4W
- americanas.com.br immediately sends RST_STREAM HOT 16
- Missed to modify member variable name HOT 1
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from curl.