Hi there,

Our program runs with libcurl version 7.55.1 on Ubuntu 16.04. The request
protocol could be either HTTP or HTTPS.

We use multi interface with curl_multi_socket_action. For each easy handle,
we configure the CURLOPT_TIMEOUT_MS and CURLOPT_CONNECTTIMEOUT_MS to be
10000ms and expect them to finish/timeout within the time. It works most of
the time. However, rarely there are requests that never finish. We
periodically do Curl_multi_dump() and confirm the easy handles are active
even after hours.

I did some investigations and think there is discrepancy between expire
time and Curl_timeleft calculation. EXPIRE_TIMEOUT/EXPIRE_CONNECTTIMEOUT
timeouts are smaller than (t_startsingle/t_startop + configured timeout).
My proposed fix is to set corresponding expire time after t_startsingle and
t_startop are set.

Have you seen a similar problem?
Thanks!

The following are my investigations:
I dump the multitree, confirm the long running handle is not in the tree.
Take an example, one easy handle has state WAITCONNECT, 1 sockets, 105 [
TX] timeleft -11789ms now 13885.458358 start 13863.648958 t_startsingle
13863.670132 t_startop 13863.649013.

I added the following logging in multi_addtimeout(). The most recent
timeout is [13873.648975 eid EXPIRE_CONNECTTIMEOUT]

*Jan 18 23:03:24.105 info: handle 0x708017f5ea48 add timeout 13863.648853
eid EXPIRE_RUN_NOW*
*Jan 18 23:03:24.105 info: handle 0x708017f5ea48 add timeout 13873.648958
eid EXPIRE_TIMEOUT*
*Jan 18 23:03:24.105 info: handle 0x708017f5ea48 add timeout 13873.648975
eid EXPIRE_CONNECTTIMEOUT*
*Jan 18 23:03:24.106 info: handle 0x708017f5ea48 add timeout 13863.649936
eid EXPIRE_RUN_NOW*
*Jan 18 23:03:24.127 info: handle 0x708017f5ea48 add timeout 13863.671231
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.127 info: handle 0x708017f5ea48 add timeout 13863.670289
eid EXPIRE_RUN_NOW*
*Jan 18 23:03:24.127 info: handle 0x708017f5ea48 add timeout 13863.671380
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.128 info: handle 0x708017f5ea48 add timeout 13863.673571
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.130 info: handle 0x708017f5ea48 add timeout 13863.677785
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.134 info: handle 0x708017f5ea48 add timeout 13863.685972
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.143 info: handle 0x708017f5ea48 add timeout 13863.702151
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.159 info: handle 0x708017f5ea48 add timeout 13863.734796
eid EXPIRE_ASYNC_NAME*
*Jan 18 23:03:24.192 info: handle 0x708017f5ea48 add timeout 13863.935038
eid EXPIRE_HAPPY_EYEBALLS*

I added log in multi_runsingle(), confirm it ran at 13873.649452
when EXPIRE_CONNECTTIMEOUT is reached.
*Jan 18 23:03:34.106 info: runsingle: multi 0x708022913cc8, handle
0x708017f5ea48 now 13873.649452*

However, the Curl_timeleft() does not think it time out.
13873.648975 (EXPIRE_CONNECTTIMEOUT) < 13873.649452 (runsingle now)
< 13863.670132 +10 (during connect: t_startsingle + configured timeout)
It is a very small time window, so it does not happen every time.

-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.haxx.se/mail/etiquette.html
Received on 2019-01-25