Re: Asiohiper example program delay

2018-05-24 Thread Daniel Stenberg

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

2018-05-23 Thread Daniel Stenberg

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 Stenberg 
Date: 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

2018-05-18 Thread Sean Miller
> 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

2018-05-17 Thread Daniel Stenberg

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

2018-05-17 Thread Sean Miller
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