[OpenSIPS-Users] first async(rest_post) timeout fail

[Liviu Chircu]

If libcurl tells us we have to wait 3 seconds... we must oblige :)

Also, that useful extra logging is going to make it into all future 
OpenSIPS versions from now on!

Glad everything is working well,

Liviu Chircu
OpenSIPS Developer
http://www.opensips-solutions.com

On 26.02.2016 18:42, Koce wrote:
> Hello Liviu thank you for your time,you are correct I increased the 
> timeout to 5 sec and once the connections were established everything 
> was working as it should.
> I feel foolish for this but I think i learned something.
>
> Anyway here is the opensips.log with the extra logging just in case
>
> Feb 26 13:52:25  /sbin/opensips[2114]: 
> INFO:rest_client:start_async_http_req: curl_multi_timeout(): 
> retry_time is 0ms
> Feb 26 13:52:25  /sbin/opensips[2114]: 
> INFO:rest_client:start_async_http_req: curl_multi_timeout(): 
> retry_time is 2999ms
> Feb 26 13:52:28  /sbin/opensips[2114]: 
> INFO:rest_client:start_async_http_req: curl_multi_timeout() returned 
> -1, pausing 500ms...
> Feb 26 13:52:29  /sbin/opensips[2114]: 
> ERROR:rest_client:start_async_http_req: timeout while connecting to 
> 'http://192.168.100.1:2080/jsonrpc' (3 sec)
> Feb 26 13:52:29  /sbin/opensips[2114]: 
> INFO:rest_client:start_async_http_req: curl_multi_timeout(): 
> retry_time is 1ms
> Feb 26 13:52:29  /sbin/opensips[2114]: 
> INFO:rest_client:start_async_http_req: curl_multi_timeout(): 
> retry_time is 2994ms
> Feb 26 13:52:29  /sbin/opensips[2114]: RETURNED NOT NULL #xlog line 
> for async_request
> Feb 26 13:52:29  /sbin/opensips[2114]: 
> INFO:rest_client:start_async_http_req: curl_multi_timeout(): 
> retry_time is 1ms
>
>> Hello koce!
>>
>> Most likely, the issue is due to your restricting "connection_timeout =
>> 1" module parameter. To quote from libcurl's documentation [1]: /"You
>> must not wait too long (more than a few seconds perhaps)". /This is why
>> I chose that 500 ms pause time upon running into that error condition,
>> which is basically 50% of your allowed blocking time already!
>>
>> To better understand how much libcurl expects you to wait, you can apply
>> an extra logging patch:
>>
>> /git apply <(wget -qO -
>> http://opensips.org/patches/rest_client_connect_timeout_logging.patch)
>>
>> /Please re-compile your rest_client and re-run the test, and we'll draw
>> final conclusions afterwards!
>>
>> [1]: https://curl.haxx.se/libcurl/c/curl_multi_timeout.html
>>
>> Best regards,
>>
>> Liviu Chircu
>> OpenSIPS Developer
>> http://www.opensips-solutions.com
>>
>> On 23.02.2016 15:46, koce at mentalchallenge.tk wrote:
>>> Hello I'm using OpenSIPS 2.1 latest from git and every time I call the
>>> first async(rest_post) function from my script I experience
>>> timeout,and the other calls to async(rest_post) after that point in
>>> the script are OK, as if the first call is like a ping to the http
>>> server it does not send any data to it,it only completes the TCP
>>> handshake.
>>>   But if I put a dummy rest_post() function in front of the first
>>> async(rest_post) it will send the data that is assigned to it and
>>> after that the first async(rest_post) call and the rest that follow
>>> will execute as planned.
>>> To test if there is something wrong with the server that I'm
>>> connecting to I tried another server that had nothing to do with the
>>> original just to see if I get the same result and YES the
>>> async(rest_post) to that server failed but the other async(rest_post)
>>> who are interacting with the original server executed without a hitch.
>>> Also I think it's related to this
>>> https://github.com/OpenSIPS/opensips/issues/493 which is closed.
>>> Could this be a possible bug,or am I missing something obvious ?
>>> Also I installed curl 7.47.1 just to make sure it wasn't libcurl in
>>> question and the same scenario happened again.
>>> the errors that I got in opensips.log
>>> ====================
>>> Feb 23 10:49:43 /sbin/opensips[25985]:
>>> INFO:rest_client:start_async_http_req: curl_multi_timeout() returned
>>> -1, pausing 500ms...
>>> Feb 23 10:49:44 /sbin/opensips[25985]:
>>> ERROR:rest_client:start_async_http_req: timeout while connecting to
>>> 'http://192.168.100.3:2080/jsonrpc' (1 sec)
>>> ====================
>>> Feb 23 12:28:08 /sbin/opensips[26219]:
>>> INFO:rest_client:start_async_http_req: curl_multi_timeout() returned
>>> -1, pausing 500ms...
>>> Feb 23 12:28:08 /sbin/opensips[26219]:
>>> ERROR:rest_client:start_async_http_req: timeout while connecting to
>>> 'http://192.168.100.2:80/jsonrpc' (1 sec)
>>> ====================
>>> NOTE: the IP's are substituted from the real ones which are public.
>>> I'm attaching 2 flows from wireshark.
>>>
>>>
>>> _______________________________________________
>>> Users mailing list
>>> Users at lists.opensips.org
>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>>
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users