Re: Asiohiper example program delay
On Thu, 24 May 2018, Sean Miller wrote: Your educated guess was correct. Log with patch applied to 7.55.1 is attached. Original observed delay is gone. What delays remain are probably network latency. Awesome! I think the fix could be slightly more polished (since it now sets the socket to wait for read + write unconditionally without checking specifically which one the underlying functions actually want), but I think I'll leave that improvement for a future rainy day! =) I've pushed this fix as a PR now in https://github.com/curl/curl/pull/2600 and once it passes the tests there, I'll merge to master. Thanks for your reports and logs! -- / daniel.haxx.se --- Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library Etiquette: https://curl.haxx.se/mail/etiquette.html
Re: Asiohiper example program delay
On Fri, 18 May 2018, Sean Miller wrote: Does it seem like that could be what happens in your case? If so, I'll write up a patch you can test... I'd be happy to test a patch. I've been poking around in the code a little myself, but I'm unfamiliar with it. I've reproduced this on libcurl-7.19.7 (RHEL6... I know...) and libcurl-7.55.1, the latter of which I build myself. Hi again, sorry it took me while to get back but attached here is a debug patch that I'd like you to apply to your code and see what debug output (and possibly changed behavior) you get. Please do another log and attach in a reply. I think might be easiest if you build 7.60.0 (or just git master) from source if we need to try out further stuff, but I won't insist on putting that on you. It would also reduce the risk that you're actually seeing the effects of a bug we've already fixed or subtly changed since 7.55.1... -- / daniel.haxx.seFrom a03eb7f616218c207b662868fbdc2579a2c8a35a Mon Sep 17 00:00:00 2001 From: Daniel StenbergDate: Thu, 24 May 2018 00:21:37 +0200 Subject: [PATCH] debug: Curl_protocol_getsock --- lib/url.c | 5 - 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/lib/url.c b/lib/url.c index 701f83ab3..fdb84267b 100644 --- a/lib/url.c +++ b/lib/url.c @@ -1552,11 +1552,14 @@ int Curl_protocol_getsock(struct connectdata *conn, curl_socket_t *socks, int numsocks) { if(conn->handler->proto_getsock) return conn->handler->proto_getsock(conn, socks, numsocks); - return GETSOCK_BLANK; + infof(conn->data, "%s:%d => debug point\n", +__FILE__, __LINE__); + socks[0] = conn->sock[FIRSTSOCKET]; + return GETSOCK_READSOCK(0) | GETSOCK_WRITESOCK(0); } int Curl_doing_getsock(struct connectdata *conn, curl_socket_t *socks, int numsocks) -- 2.17.0 --- Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library Etiquette: https://curl.haxx.se/mail/etiquette.html
Re: Asiohiper example program delay
> I think you've stepped on a libcurl bug! Uh oh. I'll have to clean off my shoe. > Are you doing HTTPS through a HTTP proxy by any chance? That's what the > PROTOCONNECT state is for basically. Yes, almost everything I do in this large private cloud goes through proxies. > Does it seem like that could be what happens in your case? If so, I'll write > up a patch you can test... I'd be happy to test a patch. I've been poking around in the code a little myself, but I'm unfamiliar with it. I've reproduced this on libcurl-7.19.7 (RHEL6... I know...) and libcurl-7.55.1, the latter of which I build myself. Regards, Sean M. --- Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library Etiquette: https://curl.haxx.se/mail/etiquette.html
Re: Asiohiper example program delay
On Thu, 17 May 2018, Sean Miller wrote: 1) In the WAITCONNECT state, libcurl calls multi_timer_cb(200) and registers interest in writing. 2) The FSM transitions first to SENDPROTOCONNECT and then to PROTOCONNECT. 3) Libcurl calls remsock() through sock_cb(). 4) ... Nothing happens until the timer fires ~165 ms later. What should the example do, if possible, to avoid this delay? I think you've stepped on a libcurl bug! Are you doing HTTPS through a HTTP proxy by any chance? That's what the PROTOCONNECT state is for basically. While in this state, libcurl does not extract and return the correct socket to wait for and this is probably what causes this for you. I *think* this bug is present there because the CONNECT procedure was once blocking so then this state would never return a socket... and when we made that non-blocking, I probably missed this part. Does it seem like that could be what happens in your case? If so, I'll write up a patch you can test... -- / daniel.haxx.se --- Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library Etiquette: https://curl.haxx.se/mail/etiquette.html
Asiohiper example program delay
I added simple logging and a debug function to the following Boost ASIO-based example program: https://curl.haxx.se/libcurl/c/asiohiper.html Summary: 1) In the WAITCONNECT state, libcurl calls multi_timer_cb(200) and registers interest in writing. 2) The FSM transitions first to SENDPROTOCONNECT and then to PROTOCONNECT. 3) Libcurl calls remsock() through sock_cb(). 4) ... Nothing happens until the timer fires ~165 ms later. What should the example do, if possible, to avoid this delay? I appreciate any ideas/clues/hints. Until then, I'm investigating the differences between this and the other example programs. I'm including the log (trimmed to point of interest) below: 2018-05-17 21:06:11,461 INFO root - opensocket: 2018-05-17 21:06:11,461 INFO root - from libcurl: Trying 172.217.12.4... 2018-05-17 21:06:11,461 INFO root - from libcurl: TCP_NODELAY set 2018-05-17 21:06:11,461 INFO root - from libcurl: STATE: WAITRESOLVE => WAITCONNECT handle 0x1d97188; line 1539 (connection #0) 2018-05-17 21:06:11,461 INFO root - sock_cb (sock=6, what=2) 2018-05-17 21:06:11,461 INFO root - sock_cb: adding data: OUT 2018-05-17 21:06:11,461 INFO root - addsock (action=2) 2018-05-17 21:06:11,461 INFO root - setsock (sock=6, action=2, oldact=0) 2018-05-17 21:06:11,461 INFO root - setsock: watching for socket to become writable 2018-05-17 21:06:11,461 INFO root - multi_timer_cb (timeout_ms=200) 2018-05-17 21:06:11,461 INFO root - check_multi_info; remaining=1 2018-05-17 21:06:11,494 INFO root - event_cb (sock=6, action=2) 2018-05-17 21:06:11,494 INFO root - event_cb: running multi socket action 2018-05-17 21:06:11,494 INFO root - from libcurl: Connected to www.google.com (172.217.12.4) port 80 (#0) 2018-05-17 21:06:11,494 INFO root - from libcurl: STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x1d97188; line 1591 (connection #0) 2018-05-17 21:06:11,494 INFO root - from libcurl: Marked for [keep alive]: HTTP default 2018-05-17 21:06:11,494 INFO root - from libcurl: STATE: SENDPROTOCONNECT => PROTOCONNECT handle 0x1d97188; line 1605 (connection #0) 2018-05-17 21:06:11,494 INFO root - sock_cb (sock=6, what=4) 2018-05-17 21:06:11,494 INFO root - remsock 2018-05-17 21:06:11,494 INFO root - check_multi_info; remaining=1 2018-05-17 21:06:11,494 INFO root - event_cb: keep watching...? 2018-05-17 21:06:11,662 INFO root - timer_cb: 2018-05-17 21:06:11,662 INFO root - from libcurl: STATE: PROTOCONNECT => DO handle 0x1d97188; line 1626 (connection #0) 2018-05-17 21:06:11,662 INFO root - from libcurl: STATE: DO => DO_DONE handle 0x1d97188; line 1688 (connection #0) 2018-05-17 21:06:11,662 INFO root - from libcurl: STATE: DO_DONE => WAITPERFORM handle 0x1d97188; line 1813 (connection #0) 2018-05-17 21:06:11,662 INFO root - from libcurl: STATE: WAITPERFORM => PERFORM handle 0x1d97188; line 1823 (connection #0) 2018-05-17 21:06:11,662 INFO root - sock_cb (sock=6, what=1) 2018-05-17 21:06:11,662 INFO root - sock_cb: adding data: IN 2018-05-17 21:06:11,662 INFO root - addsock (action=1) 2018-05-17 21:06:11,662 INFO root - setsock (sock=6, action=1, oldact=0) 2018-05-17 21:06:11,662 INFO root - setsock: watching for socket to become readable 2018-05-17 21:06:11,662 INFO root - multi_timer_cb (timeout_ms=1000) 2018-05-17 21:06:11,662 INFO root - check_multi_info; remaining=1 Thanks, Sean M. --- Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library Etiquette: https://curl.haxx.se/mail/etiquette.html