#1243 when timeout, CURLINFO_TOTAL_TIME is not ok

[he qin]

hi

When I use the multi handle to process one easy handle, I set 80ms timeout for the easy handle. If timeout occur, I get the CURLINFO_TOTAL_TIME, the result is 0? why not 80ms?

Read the code, I found, when timeout occur, I call

curl_multi_socket_action(
multi,
CURL_SOCKET_TIMEOUT,
0,
&still_running);

I see that the CURLINFO_TOTAL_TIME will be update in Curl_done->Curl_pgrsDone. But , as above code, when curl_multi_socket_action was called use CURL_SOCKET_TIMEOUT as the second arg, curl_multi_socket_action will do nothing....(in multi_socket function , all "if" is false)

If I want to get the realtime for CURLINFO_TOTAL_TIME, how to do ?

[Daniel Stenberg]

Sounds like a bug, yes. Do you have any suggested patch? Do you have a small example code we can use to repeat the problem with?

Which libcurl version have you tried this with?

[he qin]

thank you for your reply, I use the nearest version : curl-7.30.0

here is my example (just a little modification for curl-7.30.0/docs/examples/hiperfifo.c, here I use the nearest version of libevent)

---

see the attachment.

use this command to build:

gcc hiperfifo.c -I../../include -I ../../../../libevent-2.0.21-stable/include -lcurl -L ../../lib/.libs/ -levent -L ../../../../libevent-2.0.21-stable/.libs/ -Wl,-rpath=../../lib/.libs/:../../../../libevent-2.0.21-stable/.libs/

---

you can use an illegal url to test, like this:

echo 'http://123.456.com' > hiper.fifo

the result is :

heqin@ubuntu:~/source/test/curl-7.30.0/docs/examples$ ./a.out
Creating named pipe "hiper.fifo"
Now, pipe some URL's into > hiper.fifo
Adding easy 0x9005710 to multi 0x8ffe590 (http://123.456.com)
multi_timer_cb: Setting timeout to 1 ms

• Closing connection 0
  multi_timer_cb: Setting timeout to 79 ms
  REMAINING: 0
  DONE: http://123.456.com/ => (28) , use = 0 ms
  multi_timer_cb: Setting timeout to -1 ms
  REMAINING: 0

---

now, I don't have any idea for fixing this. I found that in curl_multi_remove_handle function, it will call the Curl_done->Curl_pgrsDone to flush the total time, but after calling curl_multi_remove_handle function, the easy handle will be Not available, and the total time is not exact because the total time is depending on the time of calling the curl_multi_remove_handle.

I think we can call the Curl_done function when timeout occur, but I don't try it. just a little suggestion :)

[Daniel Stenberg]

Okay thanks, can you check and see if this little patch makes any difference?

[he qin]

I tried it , not ok.

I read the code, when the case(timeout) occur, the "easy->easy_conn" is NULL(because no connect in that case). so, I think should the function "Curl_pgrsUpdate" is called not in
if(easy->easy_conn &&
(easy->state >= CURLM_STATE_CONNECT) &&
(easy->state < CURLM_STATE_COMPLETED)) { //here }

maybe need edit some other place(set value to easy->easy_conn, otherwise no place to store the "progress.timespent") ... but I don't know where :)

[Daniel Stenberg]

Ah, of course. Thanks for testing and digging further. It also made me realize we can do this a bit nicer in the code. See my new patch attached here.

It grew bigger now only because I decided to clean up Curl_pgrsUpdate() while at it to take another struct as input argument.

I have more hope that this approach works!

[Daniel Stenberg]

Oops, it used the timeout logic before the start time was set properly. New patch with the TIMER_STARTSINGLE call moved to the init state!

[he qin]

It's not ok...

I found that I made a mistake. Follow the code, the callings as follows in my case:

----curl_multi_socket_action
--------multi_socket, checkall(0), s != CURL_SOCKET_TIMEOUT(0)
------------multi_runsingle, data=0x939b710, state=0, conn=(nil)
__Curl_pgrsStartNow
------------state=2, result=0, conn=(nil)
------------multi_runsingle over
------------multi_runsingle, data=0x939b710, state=2, conn=(nil)

• Closing connection 0
  ------------state=2, result=28, conn=(nil)
  ------------multi_runsingle over
  --------multi_socket over
  ----curl_multi_socket_action end

actually, when multi_runsingle is called in the second time, the state == 2(CURLM_STATE_CONNECT) and the result == 28 (!= CURLE_OK). code here:

if(easy->state < CURLM_STATE_COMPLETED) {
  if(CURLE_OK != easy->result) {
    /*

     * If an error was returned, and we aren't in completed state now,
     * then we go to completed and consider this transfer aborted.
     */

    /* NOTE: no attempt to disconnect connections must be made
       in the case blocks above - cleanup happens only here */

    data->state.pipe_broke = FALSE;

    if(easy->easy_conn) {//no exec...}

    else if(easy->state == CURLM_STATE_CONNECT) {//exec here
      /* Curl_connect() failed */
      (void)Curl_posttransfer(data);
    }

    multistate(easy, CURLM_STATE_COMPLETED);//set status to CURLM_STATE_COMPLETED
  }

  //......

 if(CURLM_STATE_COMPLETED == easy->state) { //at once, set the result to application
/* now fill in the Curl_message with this info */
msg = &easy->msg;

msg->extmsg.msg = CURLMSG_DONE;
msg->extmsg.easy_handle = data;
msg->extmsg.data.result = easy->result;

result = multi_addmsg(multi, msg);

multistate(easy, CURLM_STATE_MSGSENT);

}

In hiperfifo.c:

1. curl_multi_add_handle will call update_timer, and update_timer will call multi->timer_cb with timeout_ms=1

2.in my multi->timer_cb, I set a 1ms' timer event. And after 1ms, the libevent will wake up and exec :
curl_multi_socket_action(multi,
CURL_SOCKET_TIMEOUT, 0, &g->still_running);

3.after the second step, immediately I call
while ((msg = curl_multi_info_read(g->multi, &msgs_left))) {...}

as above, the total time will be zero, because the first call of curl_multi_socket_action set its over status.

I don't know whether you know what I mean. Actually, no bug for curl, just Curl_connect() failed , curl think it's over, no time to spent, so zero is reasonable.

But I think, in my case, the return code 28 is confusing. Maybe in this case , curl return 6 or 7 will be much easier to understand for me.

   6      Couldn't resolve host. The given remote host was not resolved.

   7      Failed to connect to host.

   28     Operation timeout. The specified time-out period was reached according to the conditions.

[Daniel Stenberg]

Hm, so which function/code decides to set the return code 28 (CURLE_OPERATION_TIMEDOUT) in this case?

[he qin]

sorry, I lose one line code for the example
curl_easy_setopt(conn->easy, CURLOPT_NOSIGNAL, 1);
(if not set this, in Curl_resolv_timeout function, check timeout < 1000 or not, it use alarm trigger timeout, the minimum timeout must be bigger than 1000)

if(timeout < 1000)
/ The alarm() function only provides integer second resolution, so if
we want to wait less than one second we must bail out already now. /
return CURLRESOLV_TIMEDOUT;

add this line, the case return errcode = 6. no problem.

But in this case, the total time is still 0. here I think libcurl can set the total time when errcode = 6 occur instead of totaltime = 0

in Curl_resolv_timeout function:

else if(!hostaddr) {
failf(data, "Couldn't resolve host '%s'", conn->host.dispname);
result = CURLE_COULDNT_RESOLVE_HOST;
/ don't return yet, we need to clean up the timeout first /
}

[Daniel Stenberg]

1. there's no "hostaddr" variable in that function

2. I disagree with your suggested change. It bails out from there due to the timeout being met, not strictly because it fails to resolve the host name...

[he qin]

You mean that when it fails to resolve the host name, the total time is not strict ? even so, the total time should be bigger than zero, it should not be zero.

Is calculation of the total time after resolve the host name ?

[Daniel Stenberg]

No, I mean that when the timeout triggers we return a timeout error code. Not a "can't resolve" one.

The mere fact that you hit the < 1000 check means you built libcurl with the stock synchronous resolver and then it will return immediately if you set a timeout time below 1000 ms since it can't deal with a lower resolution than so. This is also why it returns immediately and it does not even try to do anything in the 80 ms you've asked for. You need to rebuild with the threaded or ares resolvers to use sub second timeout resolution for the name resolving part.

[he qin]

I understand, when I don't set CURLOPT_NOSIGNAL, it will return immediately if the timeout time below 1000 ms. So I set CURLOPT_NOSIGNAL.

If I set CURLOPT_NOSIGNAL, does it mean I must use asynchronous DNS lookups ?

In libcurl docs, it suggests use c-ares. how to use c-ares? is there an example? or I just rebuild libcurl with c-ares and no any changes for application code ?

[Daniel Stenberg]

This is a specific bug report though. If you need help on how to use libcurl then the curl-library mailing list is the place to ask and get help.

With CURLOPT_NOSIGNAL set, no signals will be used to abort the synchronous name resolve so it can't timeout.

[he qin]

Thank you for your reply. I see it. ^.^