On Fri, Aug 9, 2013 at 5:48 PM, Daniel Stenberg <daniel_at_haxx.se> wrote:
> Yes. It is always one single (active) timer and it is always single-shot. If
> you get a new timeout callback (before or after the existing one expires),
> that's the new time to set for the timer.

Alright, cool. This makes it a bit more complicated, as there's no way
to cancel a dispatch_after() call to change an existing timeout. Will
I run into issues if I leave the previous timeout running after
creating a new one? It would cause an extra call to
curl_multi_socket_action(), and I'm not sure how much damage this
could cause. If it's a bad idea, then I'll have to use the timer
source as I am now, with some trickery to have it cancel itself after
a single run. Probably not too difficult, but not very clean.

> Sorry, I was a bit rusty with the specific details but I read up on the
> source code and I also just updated the curl_multi_add_handle() man page to
> clarify: when you add a new handle it will cause the timer callback to get
> called with the updated timeout timer (1ms) so when that expires you'll of
> course call curl_multi_socket_action() on that handle and then it is kicked
> off. You should of course be able to see this.
>
> Depending on what name resolver backend you use, you should get some timeout
> set after the 1ms timeout but then there's no other default timeout if I
> remember correctly and it should only be doing socket callbacks to alter
> what you should wait for.

Excellent, this appears to be (at least close to) the behavior that
I'm already seeing. I'm using the default resolver, and it doesn't
seem to set a timeout, or if it does, it's not doing it through my
TIMEOUTFUNCTION. This leads me into the new discoveries that I've
made.

I was switching over to using dispatch_after() to only run the timeout
once, just to get a jump on seeing if it even worked. While it doesn't
have any *extra* issues, it's not getting any further than it was.
However, I made progress on two issues while working on this. The
first is that I fixed the odd looking log output. Turns out that this
wasn't thread-related at all, but due to the fact that I had neglected
to limit the output to the length of the string provided to my
debug_function. Since it isn't null-terminated, it was spewing extra
copies of contents everywhere each time I printed it. That's why the
extra content got one line shorter every time it printed, because the
string was being advanced by one line of output on each call. So
that's good.

Secondly, and more importantly, I discovered that it isn't outright
hanging after dropping the control connection. I ran out of ideas and
decided to let it just sit there after running as far as it usually
does, and, lo and behold, it 15 minutes later it finally timed out
with code 55! Before stopping, it printed "150 Data Connection
Accepted", meaning that it must have received that from the server
prior to hanging. The fact that it didn't print it out prior to this
makes me think that maybe that message was stuck in the socket
somehow, and my dispatch queue sources didn't pick it up?

In addition, it called the read_function twice or so (probably just
from the false action on the socket being picked up?), print a bit of
what I assume was the contents of the test file (a jpeg, so it was
nonsense), and then finally let me know that it "timed out after x
milliseconds with 0 out of -1 bytes received". A fifteen minute
timeout was never set using my timeout_callback, so where is this
occuring? Is it within libcurl, or is this some system thing giving up
and forcing the socket closed?

This last part also makes me curious: It appears that it's letting me
know that it *downloaded* 0 out of -1 bytes, which makes sense, being
an upload. However, does that fact that it didn't tell me about the
*upload* state mean that some part of it is stuck thinking that it
should be receiving data instead of sending it? I've set
CURLOPT_UPLOAD, and it sends the STOR command to the server, so this
seems unlikely, but it made me wonder.

Finally, I'm seeing a very odd and extremely intermittent issue: every
once in a while, when I perform the upload (with no variation in the
process, at least that *I'm* causing), rather than just getting the
normal messages about reading on a socket, I see a massive amount of
writes. I'm logging it from within the dispatch source that monitors
the socket. I attached a log that shows this event, it looks identical
to a normal run other than the wall of "socket 6: write" messages. The
log also contains the timeout at the end, though it was shortened by
the addition of a CURLOPT_TIMEOUT on the easy-handle so that it isn't
taking 15 minutes anymore.

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html