Skip to content

1 second sleep in middle of curl request using rustls backend  #7064

New issue
New issue
Closed
Closed
1 second sleep in middle of curl request using rustls backend #7064
@kevinburke1

Description

@kevinburke1
kevinburke1
opened on May 14, 2021

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

Activity

jsha

jsha commented on May 14, 2021

@jsha
jsha
on May 14, 2021
Contributor

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

jsha commented on May 15, 2021

@jsha
jsha
on May 15, 2021
Contributor

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.

jsha
mentioned this on May 15, 2021
bagder
closed this as completedin c3eefa9on May 15, 2021
kevinburke1

kevinburke1 commented on May 16, 2021

@kevinburke1
kevinburke1
on May 16, 2021 · edited by kevinburke1
Author

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

kevinburke1

kevinburke1 commented on May 22, 2021

@kevinburke1
kevinburke1
on May 22, 2021
Author

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

kevinburke1 commented on May 22, 2021

@kevinburke1
kevinburke1
on May 22, 2021
Author

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

bagder

bagder commented on May 22, 2021

@bagder
bagder
on May 22, 2021
Member

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

kevinburke1
mentioned this on May 24, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

      Development

      Participants

      @bagder@jsha@kevinburke1

      Issue actions
        1 second sleep in middle of curl request using rustls backend · Issue #7064 · curl/curl