Re: [OpenSIPS-Users] first async(rest_post) timeout fail
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, k...@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@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] first async(rest_post) timeout fail
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, k...@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@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] first async(rest_post) timeout fail
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, k...@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@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
[OpenSIPS-Users] first async(rest_post) timeout fail
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. |Time | 192.168.100.1 | | | | 192.168.100.3 | |13.478816| 48460 > autodesk-nl |TCP: 48460 > autodesk-nlm [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=1116077461 TSecr=0 WS=16 | |(48460) --> (2080) | |13.479858| autodesk-nlm > 4846 |TCP: autodesk-nlm > 48460 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=1070513 TSecr=1116077461 WS=16 | |(48460) <-- (2080) | |13.479966| 48460 > autodesk-nl |TCP: 48460 > autodesk-nlm [ACK] Seq=1 Ack=1 Win=14608 Len=0 TSval=1116077461 TSecr=1070513 | |(48460) --> (2080) | |16.031527| 48460 > autodesk-nl |TCP: 48460 > autodesk-nlm [FIN, ACK] Seq=1 Ack=1 Win=14608 Len=0 TSval=1116078099 TSecr=1070513 | |(48460) --> (2080) | |16.032326| 48461 > autodesk-nl |TCP: 48461 > autodesk-nlm [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=1116078099 TSecr=0 WS=16 | |(48461) --> (2080) | |16.032378| autodesk-nlm > 4846 |TCP: autodesk-nlm > 48460 [FIN, ACK] Seq=1 Ack=2 Win=14480 Len=0 TSval=1071151 TSecr=1116078099 | |(48460) <-- (2080) | |16.032462| 48460 > autodesk-nl |TCP: 48460 > autodesk-nlm [ACK] Seq=2 Ack=2 Win=14608 Len=0 TSval=1116078100 TSecr=1071151 | |(48460) --> (2080) | |16.033143| autodesk-nlm > 4846 |TCP: autodesk-nlm > 48461 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=1071151 TSecr=1116078099 WS=16 | |(48461) <-- (2080) | |16.033239| 48461 > autodesk-nl |TCP: 48461 > autodesk-nlm [ACK] Seq=1 Ack=1 Win=14608 Len=0 TSval=1116078100 TSecr=1071151 | |(48461) --> (2080) | |16.038013| 48461 > autodesk-nl |TCP: 48461 > autodesk-nlm [PSH, ACK] Seq=1 Ack=1 Win=14608 Len=267 TSval=1116078101 TSecr=1071151 | |(48461) --> (2080) | |16.038613| autodesk-nlm > 4846 |TCP: autodesk-nlm > 48461 [ACK] Seq=1 Ack=268 Win=15552 Len=0 TSval=1071152 TSecr=1116078101 | |(48461) <-- (2080) | |16.045423| autodesk-nlm > 4846 |TCP: autodesk-nlm > 48461 [PSH, ACK] Seq=1 Ack=268 Win=15552 Len=191 TSval=1071154 TSecr=1116078101 | |(48461) <-- (2080) | |16.045572| 48461 > autodesk-nl |TCP: 48461 > autodesk-nlm [ACK] Seq=268 Ack=192 Win=15680 Len=0 TSval=1116078103 TSecr=1071154 | |(48461) --> (2080) | |16.046922| 48461 > autodesk-nl |TCP: 48461 > autodesk-nlm [PSH, ACK] Seq=268 Ack=192 Win=15680 Len=233 TSval=1116078103 TSecr=1071154 | |(48461) --> (2080) | |16.053985| autodesk-nlm > 4846
