Hi,

I pushed a few more commits (which change how stuff is printed).
You might need linux now to compile it, but I presume that isn't
much of a problem.

When grepping the output of ./http_client like so:

./http_client | egrep '^(2014|<\.\.\.)'

you get the following output, which I annotated by adding comments:

First prepare by adding 1 request and letting it finish:

2014-10-26 21:23:35.390324: : Request #1 added [now running: 1]
2014-10-26 21:23:35.392240: : Request #1 finished [now running: 0]

Fill the pipe with 6 requests:

2014-10-26 21:23:35.392276: : Request #2 added [now running: 1]
2014-10-26 21:23:35.392305: : Request #3 added [now running: 2]
2014-10-26 21:23:35.392334: : Request #4 added [now running: 3]
2014-10-26 21:23:35.392360: : Request #5 added [now running: 4]
2014-10-26 21:23:35.392387: : Request #6 added [now running: 5]
2014-10-26 21:23:35.392412: : Request #7 added [now running: 6]

The server delays the reply for all six requests with 0.5 seconds,
so here http_client is just waiting for a reply from the server.
The time that passed until the next debug line is printed:

<... 0.501581 seconds ...>

Then we receive the reply for request #2:

2014-10-26 21:23:35.893993: : Request #2 finished [now running: 5]

Fill the pipe up till we have 6 requests in the pipe again:

2014-10-26 21:23:35.895192: : Request #8 added [now running: 6]

Next we receive the reply for request #3 (shortly after #2):

2014-10-26 21:23:35.931878: : Request #3 finished [now running: 5]

Fill the pipe up till we have 6 requests in the pipe again:

2014-10-26 21:23:35.933227: : Request #9 added [now running: 6]

Next we receive a burst of the remaining 4 requests there were
initially added:

2014-10-26 21:23:35.935441: : Request #4 finished [now running: 5]
2014-10-26 21:23:35.935470: : Request #5 finished [now running: 4]
2014-10-26 21:23:35.935497: : Request #6 finished [now running: 3]
2014-10-26 21:23:35.935523: : Request #7 finished [now running: 2]

Fill the pipe up till we have 6 requests in the pipe again:

2014-10-26 21:23:35.935590: : Request #10 added [now running: 3]
2014-10-26 21:23:35.935618: : Request #11 added [now running: 4]
2014-10-26 21:23:35.935644: : Request #12 added [now running: 5]
2014-10-26 21:23:35.935672: : Request #13 added [now running: 6]

The next request was added after we waited for the first reply,
so the server still didn't a reply to that one, and here we wait
again for the server to reply until #8 is received.

<... 0.462060 seconds ...>
2014-10-26 21:23:36.397732: : Request #8 finished [now running: 5]

Immediately fill the pipe again:

2014-10-26 21:23:36.398963: : Request #14 added [now running: 6]

The next request (#9) is special: it is the first and only request
that the server delays 5 seconds (instead of 0.5 seconds). So, here
we wait for that a bit longer than before.

<... 3.535628 seconds ...>

And it didn't come in time. Here 4 seconds passed (the timeout set on
all easy handles).

2014-10-26 21:23:39.934591: : Request #9 TIMED OUT! [now running: 5]

Nevertheless, fill the pipe again.

2014-10-26 21:23:39.934727: : Request #15 added [now running: 6]

Requests #10, #11, #12, #13 and #14 were added after #9 was added
and have been in the pipe too, waiting for #9. So, they timed out too:

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]

However, request #14 was added 0.46 seconds later (after #8 was added),
it times out ~0.46 seconds later:

<... 0.465707 seconds ...>
2014-10-26 21:23:40.403146: : Request #14 TIMED OUT! [now running: 5]

HERE SOMETHING STRANGE HAPPENS. The application is NOT immediately
filling up the pipe again! See below (or next post).
0.5 seconds pass:

<... 0.531557 seconds ...>

Now we enter the top of the main loop again and the pipe is filled
up again with a new request:

2014-10-26 21:23:40.934703: : Request #20 added [now running: 6]

Even more strange, we are not receiving ANYTHING anymore from the server
or so it seems... everything that was added after #9...#14 never sees
the reply and times out:

<... 3.003190 seconds ...>
2014-10-26 21:23:43.937893: : Request #15 TIMED OUT! [now running: 5]
2014-10-26 21:23:43.938005: : Request #21 added [now running: 6]
2014-10-26 21:23:43.939778: : Request #16 TIMED OUT! [now running: 5]
2014-10-26 21:23:43.939808: : Request #17 TIMED OUT! [now running: 4]
2014-10-26 21:23:43.939888: : Request #22 added [now running: 5]
2014-10-26 21:23:43.939915: : Request #23 added [now running: 6]
2014-10-26 21:23:43.941819: : Request #18 TIMED OUT! [now running: 5]
2014-10-26 21:23:43.941847: : Request #19 TIMED OUT! [now running: 4]
2014-10-26 21:23:43.941916: : Request #24 added [now running: 5]
2014-10-26 21:23:43.941942: : Request #25 added [now running: 6]
<... 0.996732 seconds ...>
2014-10-26 21:23:44.938674: : Request #20 TIMED OUT! [now running: 5]
2014-10-26 21:23:44.938758: : Request #26 added [now running: 6]
<... 3.002391 seconds ...>
2014-10-26 21:23:47.941149: : Request #21 TIMED OUT! [now running: 5]
2014-10-26 21:23:47.941231: : Request #27 added [now running: 6]
2014-10-26 21:23:47.943428: : Request #22 TIMED OUT! [now running: 5]
2014-10-26 21:23:47.943459: : Request #23 TIMED OUT! [now running: 4]
2014-10-26 21:23:47.943579: : Request #28 added [now running: 5]
2014-10-26 21:23:47.943616: : Request #29 added [now running: 6]
2014-10-26 21:23:47.946065: : Request #24 TIMED OUT! [now running: 5]
2014-10-26 21:23:47.946097: : Request #25 TIMED OUT! [now running: 4]
2014-10-26 21:23:47.946175: : Request #30 added [now running: 5]
2014-10-26 21:23:47.946205: : Request #31 added [now running: 6]
<... 0.997387 seconds ...>
2014-10-26 21:23:48.943592: : Request #26 TIMED OUT! [now running: 5]
2014-10-26 21:23:48.943670: : Request #32 added [now running: 6]
<... 3.001739 seconds ...>
2014-10-26 21:23:51.945409: : Request #27 TIMED OUT! [now running: 5]
2014-10-26 21:23:51.947984: : Request #28 TIMED OUT! [now running: 4]
2014-10-26 21:23:51.948009: : Request #29 TIMED OUT! [now running: 3]
2014-10-26 21:23:51.950377: : Request #30 TIMED OUT! [now running: 2]
2014-10-26 21:23:51.950403: : Request #31 TIMED OUT! [now running: 1]
<... 0.997189 seconds ...>
2014-10-26 21:23:52.947592: : Request #32 TIMED OUT! [now running: 0]

Clearly that is a major bug.

I will post more details about what happens around where it goes wrong
(ignoring the rest).
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2014-10-26