cURL / Mailing Lists / curl-library / Single Mail

curl-library

timeout using curl_multi_socket_action

From: Shannon Smith <shannon.smith_at_vecima.com>
Date: Thu, 16 Jul 2015 14:28:03 -0600

I am using curl_multi_socket_action and I have based my code off the
example hiperfifo.c though I do not use a fifo to send requests like the
example does.
I am retrieving a blob of json from the remote server and am parsing it
from within the write callback. I need to be able to do about a 1000
requests at once but with only 5 requests at once only 2 or 3 of them
are completing most of the time. It seems to be a timeout problem in
libevent but I am not 100% sure.

I am using curl 7.42.0 with C in linux.

My easy setup is:

     curl_easy_setopt(easy_handle, CURLOPT_DEBUGFUNCTION, debug_callback);
     curl_easy_setopt(easy_handle, CURLOPT_URL, url);
     curl_easy_setopt(easy_handle, CURLOPT_WRITEFUNCTION,
multi_write_callback);
     curl_easy_setopt(easy_handle, CURLOPT_WRITEDATA, request);
     curl_easy_setopt(easy_handle, CURLOPT_VERBOSE, 1L);
     curl_easy_setopt(easy_handle, CURLOPT_NOPROGRESS, 0L);
     curl_easy_setopt(easy_handle, CURLOPT_XFERINFOFUNCTION,
progress_callback);
     curl_easy_setopt(easy_handle, CURLOPT_XFERINFODATA, request);
     curl_easy_setopt(easy_handle, CURLOPT_PRIVATE, request);
     // Add http headers.
     list = curl_slist_append(list, "Content-Type: application/json");
     list = curl_slist_append(list, header);
     curl_easy_setopt(easy_handle, CURLOPT_HTTPHEADER, list);

     // This sends the request to the multi curl hander that is already
running.
     if (curl_multi_add_handle(request->multi, easy_handle) != CURLM_OK)

My multi setup is:

void
init_multi_curl(
     struct multi_info *multi)
{
     // Initialize libevent.
     multi->evbase = event_base_new();
     multi->evtime = evtimer_new(multi->evbase, timer_callback, multi);
     // Initialize the multi handle.
     multi->handle = curl_multi_init();

     // Setup the socket callback and data.
     curl_multi_setopt(multi->handle, CURLMOPT_SOCKETFUNCTION,
sock_callback);
     curl_multi_setopt(multi->handle, CURLMOPT_SOCKETDATA, multi);
     // Setup the timer callback and data.
     curl_multi_setopt(multi->handle, CURLMOPT_TIMERFUNCTION,
multi_timer_callback);
     curl_multi_setopt(multi->handle, CURLMOPT_TIMERDATA, multi);
}

Essentially, I call the easy setup 5 times in a row and then call
     event_base_dispatch(multi->evbase);

Randomly some of my requests get the data and some of them fail. I
looked into the curl code a bit
and it seems that the requests that fail timeout in libevent. The data
has been retrieved from the
url and is stored in the buffer but the multi_write_callback is never
called. It seems that libevent
determines that the timer timed out and chooses not to call the
callback. I am not sure how to make this work
properly. I don't know if my debug is of any use. It is a combination of
curl debug and my own. The hex values are the easy handles.

DEBUG OUTPUT:
------------
Running "test_request_all_mapped_channels"
Request 0x609400000408
multi_timer_callback timeout 1
multi_timer_callback timeout.tv_usec 1000
Request 0x609400014408
multi_timer_callback timeout 0
multi_timer_callback timeout.tv_usec 0
Request 0x609400028408
multi_timer_callback timeout 0
multi_timer_callback timeout.tv_usec 0
Request 0x60940001e408
multi_timer_callback timeout 0
multi_timer_callback timeout.tv_usec 0
Request 0x60940003c408
multi_timer_callback timeout 0
multi_timer_callback timeout.tv_usec 0

timer_callback
-------Handle 0x60940001e408 Info: STATE: INIT => CONNECT handle
0x60940001e408; line 1048 (connection #-5000)
-------Handle 0x60940001e408 Info: Added connection 0. The cache now
contains 1 members
-------Handle 0x60940001e408 Info: Trying xxx.xx.xx.xx...
-------Handle 0x60940001e408 Info: STATE: CONNECT => WAITCONNECT handle
0x60940001e408; line 1101 (connection #0)
OPEN THE SOCKET 0x60940001e408
-------Handle 0x609400028408 Info: STATE: INIT => CONNECT handle
0x609400028408; line 1048 (connection #-5000)
-------Handle 0x609400028408 Info: Found bundle for host xxxx.xxxxx.com:
0x600800015c58
-------Handle 0x609400028408 Info: Added connection 1. The cache now
contains 2 members
-------Handle 0x609400028408 Info: Hostname xxxx.xxxxx.com was found in
DNS cache
-------Handle 0x609400028408 Info: Trying xxx.xx.xx.xx...
-------Handle 0x609400028408 Info: STATE: CONNECT => WAITCONNECT handle
0x609400028408; line 1101 (connection #1)
OPEN THE SOCKET 0x609400028408
-------Handle 0x609400014408 Info: STATE: INIT => CONNECT handle
0x609400014408; line 1048 (connection #-5000)
-------Handle 0x609400014408 Info: Found bundle for host xxxx.xxxxx.com:
0x600800015c58
-------Handle 0x609400014408 Info: Added connection 2. The cache now
contains 3 members
-------Handle 0x609400014408 Info: Hostname xxxx.xxxxx.com was found in
DNS cache
-------Handle 0x609400014408 Info: Trying xxx.xx.xx.xx...
-------Handle 0x609400014408 Info: STATE: CONNECT => WAITCONNECT handle
0x609400014408; line 1101 (connection #2)
OPEN THE SOCKET 0x609400014408
-------Handle 0x609400000408 Info: STATE: INIT => CONNECT handle
0x609400000408; line 1048 (connection #-5000)
-------Handle 0x609400000408 Info: Found bundle for host xxxx.xxxxx.com:
0x600800015c58
-------Handle 0x609400000408 Info: Added connection 3. The cache now
contains 4 members
-------Handle 0x609400000408 Info: Hostname xxxx.xxxxx.com was found in
DNS cache
-------Handle 0x609400000408 Info: Trying xxx.xx.xx.xx...
-------Handle 0x609400000408 Info: STATE: CONNECT => WAITCONNECT handle
0x609400000408; line 1101 (connection #3)
OPEN THE SOCKET 0x609400000408
multi_timer_callback timeout 0
multi_timer_callback timeout.tv_usec 0
timer_callback
-------Handle 0x60940003c408 Info: STATE: INIT => CONNECT handle
0x60940003c408; line 1048 (connection #-5000)
-------Handle 0x60940003c408 Info: Found bundle for host xxxx.xxxxx.com:
0x600800015c58
-------Handle 0x60940003c408 Info: Added connection 4. The cache now
contains 5 members
-------Handle 0x60940003c408 Info: Hostname xxxx.xxxxx.com was found in
DNS cache
-------Handle 0x60940003c408 Info: Trying xxx.xx.xx.xx...
-------Handle 0x60940003c408 Info: STATE: CONNECT => WAITCONNECT handle
0x60940003c408; line 1101 (connection #4)
OPEN THE SOCKET 0x60940003c408
multi_timer_callback timeout 1
multi_timer_callback timeout.tv_usec 1000
timer_callback
multi_timer_callback timeout 199
multi_timer_callback timeout.tv_usec 199000
-------Handle 0x60940001e408 Info: Connected to xxxx.xxxxx.com
(xxx.xx.xx.xx) port 80 (#0)
-------Handle 0x60940001e408 Info: STATE: WAITCONNECT =>
SENDPROTOCONNECT handle 0x60940001e408; line 1197 (connection #0)
-------Handle 0x60940001e408 Info: Marked for [keep alive]: HTTP default
-------Handle 0x60940001e408 Info: STATE: SENDPROTOCONNECT => DO handle
0x60940001e408; line 1215 (connection #0)
-------Handle 0x60940001e408 Info: STATE: DO => DO_DONE handle
0x60940001e408; line 1305 (connection #0)
-------Handle 0x60940001e408 Info: STATE: DO_DONE => WAITPERFORM handle
0x60940001e408; line 1432 (connection #0)
-------Handle 0x60940001e408 Info: STATE: WAITPERFORM => PERFORM handle
0x60940001e408; line 1445 (connection #0)
226 event_callback action 2 running 5
-------Handle 0x609400000408 Info: Connected to xxxx.xxxxx.com
(xxx.xx.xx.xx) port 80 (#3)
-------Handle 0x609400000408 Info: STATE: WAITCONNECT =>
SENDPROTOCONNECT handle 0x609400000408; line 1197 (connection #3)
-------Handle 0x609400000408 Info: Marked for [keep alive]: HTTP default
-------Handle 0x609400000408 Info: STATE: SENDPROTOCONNECT => DO handle
0x609400000408; line 1215 (connection #3)
-------Handle 0x609400000408 Info: STATE: DO => DO_DONE handle
0x609400000408; line 1305 (connection #3)
-------Handle 0x609400000408 Info: STATE: DO_DONE => WAITPERFORM handle
0x609400000408; line 1432 (connection #3)
-------Handle 0x609400000408 Info: STATE: WAITPERFORM => PERFORM handle
0x609400000408; line 1445 (connection #3)
226 event_callback action 2 running 5
-------Handle 0x609400028408 Info: Connected to xxxx.xxxxx.com
(xxx.xx.xx.xx) port 80 (#1)
-------Handle 0x609400028408 Info: STATE: WAITCONNECT =>
SENDPROTOCONNECT handle 0x609400028408; line 1197 (connection #1)
-------Handle 0x609400028408 Info: Marked for [keep alive]: HTTP default
-------Handle 0x609400028408 Info: STATE: SENDPROTOCONNECT => DO handle
0x609400028408; line 1215 (connection #1)
-------Handle 0x609400028408 Info: STATE: DO => DO_DONE handle
0x609400028408; line 1305 (connection #1)
-------Handle 0x609400028408 Info: STATE: DO_DONE => WAITPERFORM handle
0x609400028408; line 1432 (connection #1)
-------Handle 0x609400028408 Info: STATE: WAITPERFORM => PERFORM handle
0x609400028408; line 1445 (connection #1)
226 event_callback action 2 running 5
-------Handle 0x609400014408 Info: Connected to xxxx.xxxxx.com
(xxx.xx.xx.xx) port 80 (#2)
-------Handle 0x609400014408 Info: STATE: WAITCONNECT =>
SENDPROTOCONNECT handle 0x609400014408; line 1197 (connection #2)
-------Handle 0x609400014408 Info: Marked for [keep alive]: HTTP default
-------Handle 0x609400014408 Info: STATE: SENDPROTOCONNECT => DO handle
0x609400014408; line 1215 (connection #2)
-------Handle 0x609400014408 Info: STATE: DO => DO_DONE handle
0x609400014408; line 1305 (connection #2)
-------Handle 0x609400014408 Info: STATE: DO_DONE => WAITPERFORM handle
0x609400014408; line 1432 (connection #2)
-------Handle 0x609400014408 Info: STATE: WAITPERFORM => PERFORM handle
0x609400014408; line 1445 (connection #2)
226 event_callback action 2 running 5
-------Handle 0x60940003c408 Info: Connected to xxxx.xxxxx.com
(xxx.xx.xx.xx) port 80 (#4)
-------Handle 0x60940003c408 Info: STATE: WAITCONNECT =>
SENDPROTOCONNECT handle 0x60940003c408; line 1197 (connection #4)
-------Handle 0x60940003c408 Info: Marked for [keep alive]: HTTP default
-------Handle 0x60940003c408 Info: STATE: SENDPROTOCONNECT => DO handle
0x60940003c408; line 1215 (connection #4)
-------Handle 0x60940003c408 Info: STATE: DO => DO_DONE handle
0x60940003c408; line 1305 (connection #4)
-------Handle 0x60940003c408 Info: STATE: DO_DONE => WAITPERFORM handle
0x60940003c408; line 1432 (connection #4)
-------Handle 0x60940003c408 Info: STATE: WAITPERFORM => PERFORM handle
0x60940003c408; line 1445 (connection #4)
event_callback action 2 running 5
-------Handle 0x609400028408 Info: HTTP 1.1 or later with persistent
connection, pipelining supported
0x609400028408 multi_write_callback
event_callback action 1 running 5
0x609400028408 multi_write_callback
event_callback action 1 running 5
0x609400028408 multi_write_callback
event_callback action 1 running 5
0x609400028408 multi_write_callback
event_callback action 1 running 5
0x609400028408 multi_write_callback
event_callback action 1 running 5
0x609400028408 multi_write_callback
event_callback action 1 running 5
0x609400028408 multi_write_callback
DONE PARSING JSON 172 0x609400028408 multi_write_callback 0x42aac4

Channel 24 programs 32
-------Handle 0x609400028408 Info: STATE: PERFORM => DONE handle
0x609400028408; line 1615 (connection #1)
-------Handle 0x609400028408 Info: Connection #1 to host xxxx.xxxxx.com
left intact
CLOSE THE SOCKET 0x609400028408
event_callback action 1 running 4
-------Handle 0x609400014408 Info: HTTP 1.1 or later with persistent
connection, pipelining supported
0x609400014408 multi_write_callback
-------Handle 0x609400014408 Info: STATE: PERFORM => DONE handle
0x609400014408; line 1615 (connection #2)
-------Handle 0x609400014408 Info: Connection #2 to host xxxx.xxxxx.com
left intact
CLOSE THE SOCKET 0x609400014408
event_callback action 1 running 3
-------Handle 0x60940001e408 Info: HTTP 1.1 or later with persistent
connection, pipelining supported
0x60940001e408 multi_write_callback
-------Handle 0x60940001e408 Info: STATE: PERFORM => DONE handle
0x60940001e408; line 1615 (connection #0)
-------Handle 0x60940001e408 Info: Connection #0 to host xxxx.xxxxx.com
left intact
CLOSE THE SOCKET 0x60940001e408
event_callback action 1 running 2
-------Handle 0x60940003c408 Info: HTTP 1.1 or later with persistent
connection, pipelining supported
0x60940003c408 multi_write_callback
-------Handle 0x60940003c408 Info: STATE: PERFORM => DONE handle
0x60940003c408; line 1615 (connection #4)
-------Handle 0x60940003c408 Info: Connection #4 to host xxxx.xxxxx.com
left intact
CLOSE THE SOCKET 0x60940003c408
event_callback action 1 running 1
-------Handle 0x609400000408 Info: HTTP 1.1 or later with persistent
connection, pipelining supported
0x609400000408 multi_write_callback
event_callback action 1 running 1
0x609400000408 multi_write_callback
event_callback action 1 running 1
0x609400000408 multi_write_callback
DONE PARSING JSON 172 0x609400000408 multi_write_callback 0x42aac4

Channel 26 programs 42
-------Handle 0x609400000408 Info: STATE: PERFORM => DONE handle
0x609400000408; line 1615 (connection #3)
-------Handle 0x609400000408 Info: Connection #3 to host xxxx.xxxxx.com
left intact
CLOSE THE SOCKET 0x609400000408
event_callback action 1 running 0
timer_callback

Channel 26 page 3: COMPLETED
Channel 200 page 5: FAILED
Channel 24 page 2: COMPLETED
Channel 312 page 4: FAILED
Channel 440 page 1: FAILED

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2015-07-16