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
