1 second sleep in middle of curl request using rustls backend

[kevinburke1]

Using curl tip and crustls 0.5.0, requests will sleep for 1 second before downloading the response body. Per discussion with @jsha it sounds like this can happen if we fail to read all of the bytes from the socket before returning - there is a 1 second timeout on the select.

Here's a sample gist where you can see this happening: https://gist.github.com/kevinburkemeter/308a7349f6cd8ba1cdfe3446990b1718

[jsha]

I initially thought this was an issue in rustls alone, but I tried a few different configurations:

rustls + hyper: reproduces
rustls + curl http: no repro
openssl + hyper: no repro

So it seems like it requires both rustls and hyper to tickle this particular bug.

[jsha]

Some more details, with rustls + hyper:

strace -f -e trace=poll,recvfrom,sendto ./src/curl -s -I https://jsonip.com -vvv 2>&1 | ts %.S | tee /tmp/log
...
35.042992 recvfrom(5, "\27\3\3\1\36\256\241\34\300\21J\276\356\177\260$\325\37\350\333\260\215.\314yJ\320\301R\v\204\323"..., 18437, 0, NULL, NULL) = 291                                                          
35.043254 * EOF from rustls_client_session_read                                                                                                                                                                    
35.043749 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)                                                                                                         
35.043884 * sread: EAGAIN or EWOULDBLOCK                                                                                                                                                                           
35.044038 * EOF from rustls_client_session_read                                                                                                                                                                    
35.044188 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)                                                                                                         
35.044327 * sread: EAGAIN or EWOULDBLOCK        
35.044724 * EOF from rustls_client_session_read
36.046228 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1000) = 0 (Timeout)
36.046565 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
36.047594 * HTTP 1.1 or later with persistent connection
...

full log

``` 34.816603 poll([{fd=3, events=POLLIN}], 1, 0) = 0 (Timeout) 34.816672 * STATE: INIT => CONNECT handle 0x55cf9603c3f8; line 1751 (connection #-5000) 34.816690 * Added connection 0. The cache now contains 1 members 34.816701 strace: Process 645459 attached 34.816711 * STATE: CONNECT => RESOLVING handle 0x55cf9603c3f8; line 1797 (connection #0) 34.816721 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816731 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816741 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1 34.816752 [pid 645459] poll([{fd=7, events=POLLOUT}], 1, 0) = 1 ([{fd=7, revents=POLLOUT}]) 34.816763 [pid 645459] poll([{fd=7, events=POLLIN}], 1, 5000 34.816773 [pid 645458] <... poll resumed>) = 0 (Timeout) 34.816783 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816794 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816804 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816815 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816825 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816836 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816847 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 3) = 0 (Timeout) 34.816857 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816867 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 3) = 0 (Timeout) 34.816879 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816892 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 3) = 0 (Timeout) 34.816902 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.816914 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 3 34.816925 [pid 645459] <... poll resumed>) = 1 ([{fd=7, revents=POLLIN}]) 34.816934 [pid 645459] recvfrom(7, "p\34\201\200\0\1\0\1\0\0\0\0\6jsonip\3com\0\0\1\0\1\300\f\0\1"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [28->16]) = 44 34.816945 [pid 645459] poll([{fd=7, events=POLLIN}], 1, 4977 34.816955 [pid 645458] <... poll resumed>) = 0 (Timeout) 34.816967 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.818750 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 3) = 0 (Timeout) 34.819893 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.826908 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 7 34.826976 [pid 645459] <... poll resumed>) = 1 ([{fd=7, revents=POLLIN}]) 34.826991 [pid 645458] <... poll resumed>) = 0 (Timeout) 34.827132 [pid 645458] poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1 34.827172 [pid 645459] recvfrom(7, "\320\37\201\200\0\1\0\1\0\0\0\0\6jsonip\3com\0\0\34\0\1\300\f\0\34"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [28->16]) = 56 34.827719 [pid 645459] sendto(7, {{len=20, type=RTM_GETADDR, flags=NLM_F_REQUEST|NLM_F_DUMP, seq=1621043614, pid=0}, {ifa_family=AF_UNSPEC, ...}}, 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20 34.828106 [pid 645458] <... poll resumed>) = 0 (Timeout) 34.828144 [pid 645459] sendto(6, "\1", 1, MSG_NOSIGNAL, NULL, 0) = 1 34.828271 [pid 645459] +++ exited with 0 +++ 34.828344 * family0 == v6, family1 == v4 34.828465 * Trying 2600:3c01::f03c:91ff:fe79:43b:443... 34.828740 * STATE: RESOLVING => CONNECTING handle 0x55cf9603c3f8; line 1879 (connection #0) 34.828788 poll([{fd=5, events=POLLPRI|POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) 34.840929 poll([{fd=5, events=POLLOUT}, {fd=3, events=POLLIN}], 2, 12) = 0 (Timeout) 34.841007 poll([{fd=5, events=POLLPRI|POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) 34.842027 poll([{fd=5, events=POLLOUT}, {fd=3, events=POLLIN}], 2, 1) = 0 (Timeout) 34.842063 poll([{fd=5, events=POLLPRI|POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) 34.871668 poll([{fd=5, events=POLLOUT}, {fd=3, events=POLLIN}], 2, 187) = 1 ([{fd=5, revents=POLLOUT}]) 34.871824 poll([{fd=5, events=POLLPRI|POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=5, revents=POLLOUT|POLLWRNORM}]) 34.872472 * Connected to jsonip.com (2600:3c01::f03c:91ff:fe79:43b) port 443 (#0) 34.872567 * STATE: CONNECTING => PROTOCONNECT handle 0x55cf9603c3f8; line 1942 (connection #0) 34.873308 * offering ALPN for HTTP/1.1 and HTTP/2 34.896651 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}, {fd=5, events=POLLPRI|POLLOUT|POLLWRNORM}], 2, 0) = 1 ([{fd=5, revents=POLLOUT|POLLWRNORM}]) 34.896714 * ClientSession wants us to write_tls. 34.896839 sendto(5, "\26\3\1\0\372\1\0\0\366\3\3\363\t|j\272\350\327}_\26\320\305\6\23\244\3303qw\n\26"..., 255, MSG_NOSIGNAL, NULL, 0) = 255 34.896877 * ClientSession wants us to read_tls. 34.897051 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 34.897089 * sread: EAGAIN or EWOULDBLOCK 34.897170 * reading would block 34.897208 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) 34.897292 * Curl_socket_check: reading would block 34.897330 * STATE: PROTOCONNECT => PROTOCONNECTING handle 0x55cf9603c3f8; line 1962 (connection #0) 34.946946 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 132) = 1 ([{fd=5, revents=POLLIN}]) 34.947284 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=5, revents=POLLIN|POLLRDNORM}]) 34.947926 * ClientSession wants us to read_tls. 34.948179 recvfrom(5, "\26\3\3\0P\2\0\0L\3\3\264\24\246Ui\212\373h\372\261X\276\223o\";\360H\2154\375"..., 18437, 0, NULL, NULL) = 2969 34.961136 * reading would block 34.961318 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}, {fd=5, events=POLLPRI|POLLOUT|POLLWRNORM}], 2, 0) = 1 ([{fd=5, revents=POLLOUT|POLLWRNORM}]) 34.961489 * ClientSession wants us to write_tls. 34.961766 sendto(5, "\26\3\3\0f\20\0\0ba\4\207<\236>\320\34P\r}\21z\305\225 \203C\"&\361*\271"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 34.961939 sendto(5, "\24\3\3\0\1\1", 6, MSG_NOSIGNAL, NULL, 0) = 6 34.962133 sendto(5, "\26\3\3\0(\377e\241]\320\35\2419\31c\242\235>8|\332F\21!\200T\3670\236\3658\3"..., 45, MSG_NOSIGNAL, NULL, 0) = 45 34.962385 * writing would block 34.962624 * ClientSession wants us to read_tls. 34.962765 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 34.962960 * sread: EAGAIN or EWOULDBLOCK 34.963193 * reading would block 34.963307 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) 34.963497 * Curl_socket_check: reading would block 35.002630 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 65) = 1 ([{fd=5, revents=POLLIN}]) 35.002894 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=5, revents=POLLIN|POLLRDNORM}]) 35.003371 * ClientSession wants us to read_tls. 35.003497 recvfrom(5, "\26\3\3\0\312\4\0\0\306\0\0\1,\0\300m\234ON\ru\340\364\10\212\373\204\225\321\367\306\223"..., 18437, 0, NULL, NULL) = 258 35.004083 * reading would block 35.004249 * Done handshaking 35.004417 * ALPN, negotiated http/1.1 35.004589 * STATE: PROTOCONNECTING => DO handle 0x55cf9603c3f8; line 1981 (connection #0) 35.004846 * Time for the Hyper dance 35.005638 > HEAD / HTTP/1.1 35.005961 > Host: jsonip.com 35.006182 > User-Agent: curl/7.77.0-DEV 35.006261 > Accept: */* 35.006335 > 35.006482 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 35.006548 * sread: EAGAIN or EWOULDBLOCK 35.006637 * EOF from rustls_client_session_read 35.006979 sendto(5, "\27\3\3\0g\377e\241]\320\35\24181\273\10\362J\252\3H4O\303\230\334\303\n\375\350\253\362"..., 108, MSG_NOSIGNAL, NULL, 0) = 108 35.007092 * STATE: DO => DID handle 0x55cf9603c3f8; line 2039 (connection #0) 35.007183 * STATE: DID => PERFORMING handle 0x55cf9603c3f8; line 2158 (connection #0) 35.007243 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) 35.028607 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 21) = 0 (Timeout) 35.028717 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) 35.028853 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 0) = 0 (Timeout) 35.028992 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) 35.042408 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1000) = 1 ([{fd=5, revents=POLLIN}]) 35.042674 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=5, revents=POLLIN|POLLRDNORM}]) 35.042992 recvfrom(5, "\27\3\3\1\36\256\241\34\300\21J\276\356\177\260$\325\37\350\333\260\215.\314yJ\320\301R\v\204\323"..., 18437, 0, NULL, NULL) = 291 35.043254 * EOF from rustls_client_session_read 35.043749 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 35.043884 * sread: EAGAIN or EWOULDBLOCK 35.044038 * EOF from rustls_client_session_read 35.044188 recvfrom(5, 0x55cf96093530, 18437, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 35.044327 * sread: EAGAIN or EWOULDBLOCK 35.044724 * EOF from rustls_client_session_read 36.046228 poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 2, 1000) = 0 (Timeout) 36.046565 poll([{fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) 36.047594 * HTTP 1.1 or later with persistent connection 36.047837 < HTTP/1.1 200 OK 36.048195 < Server: nginx/1.16.1 36.048413 < Date: Sat, 15 May 2021 01:53:36 GMT 36.048680 < Content-Type: application/json; charset=utf-8 36.048862 < Connection: keep-alive 36.049108 < Access-Control-Allow-Origin: * 36.049397 < Access-Control-Allow-Methods: GET 36.049643 < Strict-Transport-Security: max-age=31536000; 36.049854 < 36.050030 * hyperstream is done! 36.050105 * STATE: PERFORMING => DONE handle 0x55cf9603c3f8; line 2357 (connection #0) 36.050197 * multi_done 36.050278 * Connection #0 to host jsonip.com left intact 36.050357 * Expire cleared (transfer 0x55cf9603c3f8) 36.050384 HTTP/1.1 200 OK 36.050405 Server: nginx/1.16.1 36.050430 Date: Sat, 15 May 2021 01:53:36 GMT 36.050457 Content-Type: application/json; charset=utf-8 36.050485 Connection: keep-alive 36.050511 Access-Control-Allow-Origin: * 36.050538 Access-Control-Allow-Methods: GET 36.050561 Strict-Transport-Security: max-age=31536000; 36.050576 36.050723 sendto(5, "\25\3\3\0\32\377e\241]\320\35\241;\311\372\264v\250hJ\357df'\240v\306\275o\26\246", 31, MSG_NOSIGNAL, NULL, 0) = 31 36.051575 +++ exited with 0 +++ ```

So it looks like the socket is fd=5, and poll() is correctly polling it, but for some reason is timing out after a second.

[kevinburke1]

Confirmed the sleep is gone! Thanks @bagder and @jsha

[kevinburke1]

Hi, apologies, when I noticed the "bug" was fixed I was actually using the stock OS curl, and not curl on tip. Unfortunately when I run this now, I get:

curl: (56) hyperstream: couldn't get response

If I revert commit c3eefa9, curl requests complete successfully again.

I'd reopen the ticket but I don't have the power to do that.

[kevinburke1]

I can't reproduce the 1sec sleep anymore, either, after I revert c3eefa9. So maybe I should open a new ticket.

[bagder]

Yes, please do since it might need a different analysis/fix.