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

Jump to bottom

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

Closed
kevinburke1 opened this issue May 14, 2021 · 6 comments
Closed

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

kevinburke1 opened this issue May 14, 2021 · 6 comments

Comments

@kevinburke1
Copy link

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
Copy link
Contributor

jsha commented May 14, 2021

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
Copy link
Contributor

jsha commented May 15, 2021

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 jsha mentioned this issue May 15, 2021
Closed
@bagder bagder closed this as completed in c3eefa9 May 15, 2021
@kevinburke1
Copy link
Author

kevinburke1 commented May 16, 2021 •
edited

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

@kevinburke1
Copy link
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
Copy link
Author

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

@bagder
Copy link
Member

bagder commented May 22, 2021

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

@kevinburke1 kevinburke1 mentioned this issue May 24, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Handle body on HYPER_TASK_EMPTY. jsha/curl
3 participants
@bagder @jsha @kevinburke1