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 post issue on latest curl version #7630

Closed
webispy opened this issue Aug 25, 2021 · 17 comments · Fixed by sthagen/curl-curl#209
Closed

HTTP/2 post issue on latest curl version #7630

webispy opened this issue Aug 25, 2021 · 17 comments · Fixed by sthagen/curl-curl#209
Labels

Comments

@webispy
Copy link

webispy commented Aug 25, 2021

I did this

Currently, I am developing an application that communicates with the server over HTTP/2 using curl + nghttp2 (1.44.0).

So far, I've been using curl library version 7.69.1, and it worked fine.
However, when testing with the latest curl version, a problem occurred, and the test results for each version are as follows.

  • v7.69.1 - works
  • v7.70.0 - works
  • v7.71.0 ~ v7.79.0 (or latest master) - not works

I tested each commit between 7.70.0 and 7.71.0 one by one to find the commit that made it stop working, and found that the following commit was causing the problem.

I expected the following

Sequence (normal operation case):

  1. HTTP/2 POST request start
  2. callback for CURLOPT_READFUNCTION invoked
  3. fill the buffer(the first part of the data to be sent) and return written bytes from callback
  4. HTTP/2 POST recv header from server
  5. callback for CURLOPT_READFUNCTION invoked
  6. fill the buffer(the second part of the data to be sent) and return written bytes from callback
  7. callback for CURLOPT_READFUNCTION invoked
  8. return 0 from callback (no more data to send)
  9. HTTP/2 POST recv data from server

But, after the c4e6968 commit, the step 5 of the above sequence does not proceed.

Sequence (abnormal operation case):

  1. HTTP/2 POST request start
  2. callback for CURLOPT_READFUNCTION invoked
  3. fill the buffer(the first part of the data to be sent) and return written bytes from callback
  4. HTTP/2 POST recv header from server
  5. ...waiting...
  6. HTTP/2 POST recv data from server (error response)
  7. callback for CURLOPT_READFUNCTION invoked
  8. fill the buffer(the second part of the data to be sent) and return written bytes from callback

I analyzed the curl log for debugging, and the difference between the normal operation case and the abnormal operation case is as follows.

File: lib/http2.c

static ssize_t http2_recv(struct connectdata *conn, int sockindex,
                          char *mem, size_t len, CURLcode *err)
{
  ...
  if(stream->bodystarted &&
     stream->nread_header_recvbuf < Curl_dyn_len(&stream->header_recvbuf)) {

     ...abnormal case return... (build with c4e6968 commit)
  }

  ...normal case... (build with 842f73d commit) 
}

Logs for normal case(build with 842f73d commit):

data_source_read_callback: returns 5136 bytes stream 7
http2_send returns 5136 for stream 7

Store 151 bytes headers from stream 7 at 0x1072470

http2_recv: easy 0x1071470 (stream 7) win 33533076/33554432
http2_recv: DRAIN 151 bytes stream 7!! (0x1072470 => 0x1072470)
http2_recv: returns 151 for stream 7

Logs for abnormal case(build with c4e6968 commit):

data_source_read_callback: returns 5138 bytes stream 9
http2_send returns 5138 for stream 9

Store 0 bytes headers from stream 9 at (nil)

Curl_readwrite: forcibly told to drain data (1)

http2_recv: Got 151 bytes from header_recvbuf

Curl_readwrite: forcibly told to drain data (1)
Curl_readwrite: forcibly told to drain data (1)
...

IMHO, it seems that the drained_transfer() function is not called in the above abnormal case log(the state.drain value is still remains). So in the Curl_readwrite() function, the select_res value is still set to CURL_CSELECT_IN, and the readwrite_upload() function is not called.

curl/libcurl version

curl 7.71.0-DEV

operating system

Linux (armhf)

@bagder bagder added the HTTP/2 label Aug 25, 2021
@bagder
Copy link
Member

bagder commented Aug 26, 2021

Thanks a lot for your report!

Can I ask you to provide us with more details on exactly how to go ahead and repeat this. Preferably with a command line or a stand-alone program we can run from our ends against a public URL to trigger the problem?

@webispy
Copy link
Author

webispy commented Aug 26, 2021

This application works by sending the user's voice data to the server and receiving the recognition result from the server as a response. (like the Alexa)
However, since it operates in Korean language, it will not be easy to setup a test environment. (Account creation through Korean website, OAuth2 token, voice utterance, etc.)
Nevertheless, if you are interested, I will temporarily share necessary information such as tokens by e-mail.

The source code is published in the Github repo below.

If you need a more detailed log (full log), I'll reproduce the issue again and share it here.
Thank you!

@bagder
Copy link
Member

bagder commented Aug 26, 2021

I ask you to write a minimum stand-alone program based on your logic, that reproduces the problem and then share that code. I cannot debug your application (unless you sign up for a support contract).

You might be able to start off with one of the libcurl examples and then adjust it to work more like your application.

@webispy
Copy link
Author

webispy commented Aug 26, 2021

Ok. As your suggestion, I will prepare an libcurl example and environment that can reproduce the issue easily.
Thank you for the information.

@webispy
Copy link
Author

webispy commented Aug 30, 2021

Hi @bagder,
The sample program created by modifying http2-upload.c in libcurl examples and the sample server written in node.js were uploaded to the repo below.

And I configured the build environment so that you can build and test it yourself easily using each of the curl commits I reported(c4e6968 and 842f73d), and also uploaded the test log.

@bagder
Copy link
Member

bagder commented Aug 30, 2021

I'm not sure when/if I'll be able to get through all that. I was hoping for a "run this code then XXX happens".

@webispy
Copy link
Author

webispy commented Aug 31, 2021

I've tried to simplify this issue. However, since it was necessary to create a situation in which two streams (GET stream and POST stream) exist at the same time to reproduce the issue, it was not easy to deliver in the form of simply sharing a piece of code. Also I had to configure and make a sample server to accept these HTTP/2 requests.

The logic of the test client(consists of about 240 lines) is simply as follows.

  1. GET request (Stream ID-1)
  2. POST request after a few seconds with stream-1 still alive (Stream ID-3)
    • The POST data is not sent all at once, but is divided and transmitted by a specific size whenever the callback registered in CURLOPT_READFUNCTION is called.

And the abnormal behavior that appears is that the CURLOPT_READFUNCTION callback is not called until the server gives a body response to the POST request.

@jay
Copy link
Member

jay commented Sep 1, 2021

I fixed the example to build for Windows (h2curl master...jay:fix_windows_build) but I'm unable to reproduce. In all cases the result was 12 seconds: 842f73d, c4e6968, e8c8775 (master at the time of testing)

packet captures of attempted windows repro curl issue 7630.zip

Edit: I used 127.5.5.5 as a alternate localhost destination server address to easily distinguish it in Wireshark from the source address 127.0.0.1

Edit 2: I did not use the submodules in the example to build curl, I used release OpenSSL/1.1.1k nghttp2/1.43.0.

@webispy
Copy link
Author

webispy commented Sep 1, 2021

Hi @jay,
Thank you so much for testing! I haven't tested it on Windows, but according to your test results, it's very interesting that everything works fine with no abnormalities.

To check whether the issue really depends on the environment, I tried running it in a clean ubuntu environment through a Github Action. And as a result, if you check the link below, you can see that the abnormal situation is reproduced.

Two jobs were run according to the curl commit, and you can see that the results(log) are different. You can also check or download the log file (Artifacts).

@jay
Copy link
Member

jay commented Sep 3, 2021

I notice libcurl is calling http2_recv continuously without wait for about 3 seconds... that doesn't look right given the example response

08:09:26.038313 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038344 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038375 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038406 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038437 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038468 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038499 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.
08:09:26.038542 Info: http2_recv: easy 0x55ca7dbd0c38 (stream 3) win 33554408/33554432
.

and so on

@bagder
Copy link
Member

bagder commented Sep 5, 2021

I wrote up a piece of code according to the description in here. It first makes a GET and then a POST with read callback over HTTP/2 with reused connection. Then ran it on linux with the latest libcurl and I see no issue.

curl 7.79.0-DEV (x86_64-pc-linux-gnu) libcurl/7.79.0-DEV OpenSSL/1.1.1l zlib/1.2.11 brotli/1.0.9 zstd/1.4.8 libidn2/2.3.2 libpsl/0.21.0 (+libidn2/2.3.0) nghttp2/1.43.0 librtmp/2.3 libgsasl/1.10.0 OpenLDAP/2.4.59

The code

issue7630.c

webispy added a commit to webispy/h2curl that referenced this issue Sep 6, 2021
add issue7630.c written by bagder
curl/curl#7630

Signed-off-by: Inho Oh <webispy@gmail.com>
webispy added a commit to webispy/h2curl that referenced this issue Sep 6, 2021
add issue7630.c written by bagder
curl/curl#7630

Signed-off-by: Inho Oh <webispy@gmail.com>
@webispy
Copy link
Author

webispy commented Sep 6, 2021

Thank you for testing. There was a typo in your code, so I modified it as follows and tested it.

--- a/issue7630.c
+++ b/issue7630.c
@@ -258,9 +258,8 @@ static CURL *get_setup(void)
  */
 int main(int argc, char **argv)
 {
-  struct input trans[NUM_HANDLES];
   CURL *upload_hnd = upload_setup();
-  CURL *get_hnd = upload_setup();
+  CURL *get_hnd = get_setup();

   curl_easy_perform(get_hnd);
   curl_easy_perform(upload_hnd);

The https://curl.se/ server that you used for testing gives a HEADER and BODY response immediately when receiving a GET request, which is different from the situation I described in the ticket.

So, I used another server(https://github.com/webispy/h2curl/blob/master/server/index.js) for testing. When this server receives a GET request, it gives only the HEADER response first, and then gives the BODY response 10 seconds later.

And as a result, the second POST request works only when the BODY response to the GET request is received.
You can see that the POST request is sent after 10 seconds as shown in the log below:

00:51:49.120251 Info: h2 header: :method:GET
00:51:49.120318 Info: Using Stream ID: 1 (easy handle 0x55dddd797158)
00:51:49.138528 Info: http2_recv: easy 0x55dddd797158 (stream 1) win 33554408/33554408
00:51:59.149131 Info: http2_recv: easy 0x55dddd797158 (stream 1) win 33554408/33554408
00:51:59.159275 Info: h2 header: :method:POST
00:51:59.159303 Info: Using Stream ID: 1 (easy handle 0x55dddd795ce8)

So my guess is that your example code doesn't fit the issue described in this ticket. (Two requests do not exist at the same time.)

@bagder
Copy link
Member

bagder commented Sep 6, 2021

your example code doesn't fit the issue described in this ticket

Then can you please adjust it so that it does? You description mentioned doing two requests over a reused connection so I made my code do that.

Two requests do not exist at the same time.

Are you now saying that the two requests need to get issued at the same time over the same connection?

@webispy
Copy link
Author

webispy commented Sep 6, 2021

To be precise, when the second POST request(Stream ID-3) is sent while the first GET request(Stream ID-1) is still alive(waiting for body response), the CURLOPT_READFUNCTION callback is not called normally.

Therefore, this situation is described as a state where two requests exist simultaneously for same connection.

I am preparing a diagram to explain this situation a little more accurately. I will try to explain it accurately through a sequence chart as soon as possible. (I apologize if I couldn't explain properly due to poor English.)

webispy added a commit to webispy/h2curl that referenced this issue Sep 6, 2021
add sequence diagram for normal and abnormal case.
curl/curl#7630

Signed-off-by: Inho Oh <webispy@gmail.com>
@webispy
Copy link
Author

webispy commented Sep 6, 2021

Please check out the two sequence charts below:

  1. Normal operation test case - build with curl 842f73d commit
    normal-sequence

  2. Abnormal operation test case - build with curl c4e6968 commit or master commit
    abnormal-sequence

@bagder
Copy link
Member

bagder commented Sep 6, 2021

Thanks for the diagram, but for me it is much more important to be able to reproduce and to check the code when the problem is triggered.

webispy added a commit to webispy/h2curl that referenced this issue Sep 9, 2021
add curl_multi to handle both get and post requests.
curl/curl#7630

Signed-off-by: Inho Oh <webispy@gmail.com>
webispy added a commit to webispy/h2curl that referenced this issue Sep 9, 2021
add curl_multi to handle both get and post requests.
curl/curl#7630

Signed-off-by: Inho Oh <webispy@gmail.com>
@webispy
Copy link
Author

webispy commented Sep 9, 2021

I modified issue7630.c you wrote to make the issue reproducible.

Please test with custom server implementation(index.js.txt, 72 lines of code) for test the GET and POST response. You can also download additional files(package.json, server.crt, server.key) needed to run the server from https://github.com/webispy/h2curl/tree/master/server.

npm install
npm start

You can also check the actual test result log at the link below.

bagder added a commit that referenced this issue Sep 10, 2021
Thus function was written to avoid doing multiple connection data
initializations, which is fine, but since it also initiates stream
related data it is crucial that it doesn't skip those even if called
again for the same connection. Solved by moving the stream
initializations before the "doing-it-again" check.

Reported-by: Inho Oh
Fixes #7630
bagder added a commit that referenced this issue Sep 10, 2021
Thus function was written to avoid doing multiple connection data
initializations, which is fine, but since it also initiates stream
related data it is crucial that it doesn't skip those even if called
again for the same connection. Solved by moving the stream
initializations before the "doing-it-again" check.

Reported-by: Inho Oh
Fixes #7630
@bagder bagder closed this as completed in 3cb8a74 Sep 11, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3 participants