HTTP/2 post issue on latest curl version

[webispy]

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.

• c4e6968 - not works
• 842f73d - works

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]

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]

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.

• https://github.com/nugu-developers/nugu-linux
• https://github.com/nugu-developers/nugu-linux/tree/master/src/base/network/http2
• https://github.com/nugu-developers/nugu-linux/tree/master/externals

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

[bagder]

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]

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

[webispy]

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.

• https://github.com/webispy/h2curl

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]

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]

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]

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]

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.

• https://github.com/webispy/h2curl/actions/runs/1189338432

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]

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]

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]

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)

• full log: https://github.com/webispy/h2curl/runs/3520126098?check_suite_focus=true

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]

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]

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]

Please check out the two sequence charts below:

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

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

[bagder]

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]

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

• issue7630_modified.c.txt (Diff: diff.txt)
• Changes:
  • Add curl_multi to handle both GET and POST requests.
  • Change the server address from "https://curl.se/" to "https://127.0.0.1:8081/"
  • Modify read_callback to send 100 bytes at a time.

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.

• https://github.com/webispy/h2curl/runs/3554481726?check_suite_focus=true (unfold the '> Test HTTP/2 POST' step)