curl-library
Re: HTTP pipelining test case
Date: Sun, 26 Oct 2014 22:18:45 +0100
This continues the previous post.
Note that the server receives all requests
and replies to all of them. So the problem
is clearly on the client side (libcurl) in
not reading the socket anymore.
If I mix the server debug output with that
of the previous post, we get:
CLIENT: (from where it got interesting)
2014-10-26 21:23:39.934591: : Request #9 TIMED OUT! [now running: 5]
2014-10-26 21:23:39.934727: : Request #15 added [now running: 6]
SERVER: (receives request #15 that was just sent)
2014-10-26 21:23:39.936015: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 15\r\n
< \r\n
CLIENT: (normal timeouts and refill)
2014-10-26 21:23:39.937200: : Request #10 TIMED OUT! [now running: 5]
2014-10-26 21:23:39.937240: : Request #11 TIMED OUT! [now running: 4]
2014-10-26 21:23:39.937265: : Request #12 TIMED OUT! [now running: 3]
2014-10-26 21:23:39.937292: : Request #13 TIMED OUT! [now running: 2]
2014-10-26 21:23:39.937359: : Request #16 added [now running: 3]
2014-10-26 21:23:39.937386: : Request #17 added [now running: 4]
2014-10-26 21:23:39.937412: : Request #18 added [now running: 5]
2014-10-26 21:23:39.937439: : Request #19 added [now running: 6]
SERVER: (receives the new refills)
2014-10-26 21:23:39.938748: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 16\r\n
< \r\n
2014-10-26 21:23:39.938982: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 17\r\n
< \r\n
2014-10-26 21:23:39.939211: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 18\r\n
< \r\n
2014-10-26 21:23:39.939446: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 19\r\n
< \r\n
CLIENT: (normal delay and timeout of the last out that SHOULD timeout)
<... 0.465707 seconds ...>
2014-10-26 21:23:40.403146: : Request #14 TIMED OUT! [now running: 5]
SERVER: (another 0.5 seconds later, the server finally sents reply #9 - and
everything that was waiting behind it, but ALSO #15 because the 0.5s
delay for that also passed by the time that #9 is ready).
2014-10-26 21:23:40.934332: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 9\r\n
> X-Reply: 9\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934485: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 10\r\n
> X-Reply: 10\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934538: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 11\r\n
> X-Reply: 11\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934589: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 12\r\n
> X-Reply: 12\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934612: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 13\r\n
> X-Reply: 13\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934645: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 14\r\n
> X-Reply: 14\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934674: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 15\r\n
> X-Reply: 15\r\n
> \r\n
> <html><body>hello</body></html>\n
CLIENT: (SOMETHING GOES WRONG HERE: the client should have read all those
replies - and disgarded the ones that already timed out, but
process #15 still - or shouldn't it? In stead the client does
nothing for a while... and then finally reaches the main loop,
where it adds another request)
<... 0.531557 seconds ...>
2014-10-26 21:23:40.934703: : Request #20 added [now running: 6]
SERVER: (The server just continues with replying with 0.5 seconds delay
on everything it receives)
2014-10-26 21:23:40.934704: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 16\r\n
> X-Reply: 16\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934732: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 17\r\n
> X-Reply: 17\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934756: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 18\r\n
> X-Reply: 18\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934780: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 19\r\n
> X-Reply: 19\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:40.934806: #2: Wrote 171 bytes.
2014-10-26 21:23:40.934812: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934817: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934821: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934826: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934830: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934835: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934840: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934844: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934849: #2: Wrote 173 bytes.
2014-10-26 21:23:40.934853: #2: Wrote 173 bytes.
AHA! At least request #20 was actually written to the server by libcurl,
and is received now:
2014-10-26 21:23:40.936634: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 20\r\n
< \r\n
Server replies 0.5 seconds later:
2014-10-26 21:23:41.436697: #2: process_replies(): writing data:
> HTTP/1.1 200 OK\r\n
> Keep-Alive: timeout=10 max=400\r\n
> Content-Length: 32\r\n
> Content-Type: text/html\r\n
> X-Connection: 2\r\n
> X-Request: 20\r\n
> X-Reply: 20\r\n
> \r\n
> <html><body>hello</body></html>\n
2014-10-26 21:23:41.436766: #2: Wrote 173 bytes.
CLIENT:
The client never sees anything anymore. Apparently
it is not looking at the socket anymore for reading,
but it is still writing to it...
<... 3.003190 seconds ...>
2014-10-26 21:23:43.937893: : Request #15 TIMED OUT! [now running: 5]
SERVER:
2014-10-26 21:23:43.939615: #2: Read 82 bytes:
< GET / HTTP/1.1\r\n
< Host: localhost:9000\r\n
< Accept: */*\r\n
< X-Sleep: 500\r\n
< X-Request: 21\r\n
< \r\n
etc.
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2014-10-26