Bug #69917 [Fbk->NoF]: curl_exec sometimes raise timeout error without even trying a connect() before

Edit report at https://bugs.php.net/bug.php?id=69917&edit=1 ID: 69917 Updated by: php-bugs@lists.php.net Reported by: maxence at typhon dot com Summary: curl_exec sometimes raise timeout error without even trying a connect() before -Status: Feedback +Status: No Feedback Type: Bug Package: cURL related Operating System: Debian 7 PHP Version: 5.6.10 Private report: N New Comment: No feedback was provided. The bug is being suspended because we assume that you are no longer experiencing the problem. If this is not the case and you are able to provide the information that was requested earlier, please do so and change the status of the bug back to "Re-Opened". Thank you. Previous Comments: ------------------------------------------------------------------------ [2019-03-26 17:42:42] mike@php.net Thank you for taking the time to report a problem with PHP. Unfortunately you are not using a current version of PHP -- the problem might already be fixed. Please download a new PHP version from http://www.php.net/downloads.php If you are able to reproduce the bug with one of the latest versions of PHP, please change the PHP version on this bug report to the version you tested and change the status back to "Open". Again, thank you for your continued support of PHP. ------------------------------------------------------------------------ [2015-08-07 06:38:10] maxence at typhon dot com You're right, simply remove the ], : <?php for ($i = 0; $i < 100000; $i++) { echo("Run ".$i."\n"); $url = "http://1.1.1.1:80/stats"; $ch = curl_init($url); $opts = [ CURLOPT_HEADER => TRUE, CURLOPT_CONNECTTIMEOUT => 1, CURLOPT_TIMEOUT => 2, CURLOPT_USERAGENT => 'curl/test' ]; curl_setopt_array($ch, $opts); $buffer = curl_exec($ch); if ($buffer === FALSE) { print("[NETWORK] HTTP request failed: ". curl_error($ch) . " - errno: ".curl_errno($ch)); exit(); } curl_close($ch); } ?> Maxence ------------------------------------------------------------------------ [2015-07-31 13:37:30] sam dot swift at fifteendigital dot co dot uk $opts = [ CURLOPT_HEADER => TRUE, CURLOPT_CONNECTTIMEOUT => 1, CURLOPT_TIMEOUT => 2, ], CURLOPT_USERAGENT => 'curl/test' ]; You have an extra square bracket ("]"), only one being opened and two being closed. ------------------------------------------------------------------------ [2015-06-24 09:26:32] maxence at typhon dot com Description: ------------ trying to diagnose why some of our requests to internal systems are failing with strange timeout errors, I tried to strace a code which reproduce the issue. It looks surprising than, when a timeout error is raised, there is no connect() tried before. Test script: --------------- <?php for ($i = 0; $i < 100000; $i++) { echo("Run ".$i."\n"); $url = "http://1.1.1.1:80/stats"; $ch = curl_init($url); $opts = [ CURLOPT_HEADER => TRUE, CURLOPT_CONNECTTIMEOUT => 1, CURLOPT_TIMEOUT => 2, ], CURLOPT_USERAGENT => 'curl/test' ]; curl_setopt_array($ch, $opts); $buffer = curl_exec($ch); if ($buffer === FALSE) { print("[NETWORK] HTTP request failed: ". curl_error($ch) . " - errno: ".curl_errno($ch)); exit(); } curl_close($ch); } ?> Expected result: ---------------- 1435133933.895389 write(1, "Run 13054\n", 10Run 13054) = 10 <0.000037> 1435133933.895491 rt_sigaction(SIGALRM, NULL, {SIG_DFL, [], SA_RESTORER, 0x7fda2e2a41e0}, 8) = 0 <0.000007> 1435133933.895538 rt_sigaction(SIGALRM, {0x7fda2ff70370, [], SA_RESTORER, 0x7fda2e2a41e0}, NULL, 8) = 0 <0.000014> 1435133933.895585 alarm(1) = 0 <0.000009> 1435133933.895618 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0 <0.000005> 1435133933.895662 time([1435133933]) = 1435133933 <0.000006> 1435133933.895710 alarm(0) = 1 <0.000006> 1435133933.895748 rt_sigaction(SIGALRM, {SIG_DFL, [], SA_RESTORER, 0x7fda2e2a41e0}, NULL, 8) = 0 <0.000006> 1435133933.895799 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3 <0.000018> 1435133933.895842 fcntl(3, F_GETFL) = 0x2 (flags O_RDWR) <0.000006> 1435133933.895878 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000005> 1435133933.895905 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("1.1.1.1")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000021> 1435133933.895970 poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 1000) = 1 ([{fd=3, revents=POLLOUT|POLLWRNORM}]) <0.000040> 1435133933.896049 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 <0.000006> 1435133933.896085 getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("1.1.1.1")}, [16]) = 0 <0.000007> 1435133933.896132 getsockname(3, {sa_family=AF_INET, sin_port=htons(38076), sin_addr=inet_addr("1.1.1.2")}, [16]) = 0 <0.000007> 1435133933.896207 sendto(3, "GET /stats HTTP/1.0\r\nUser-Agent: curl/test\r\nHost: 1.1.1.1\r\nAccept-Encoding: gzip,deflate\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\nAccept-Language: fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3\r\nAccept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\n\r\n", 302, MSG_NOSIGNAL, NULL, 0) = 302 <0.000019> 1435133933.896296 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) <0.000006> 1435133933.896347 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) <0.000006> 1435133933.896378 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 1000) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}]) <0.000007> 1435133933.896460 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}]) <0.000008> 1435133933.896507 recvfrom(3, "HTTP/1.0 200 OK\r\nServer: Nginx\r\n\r\nname: network\nsubscribers: 10\nmessages: 1\n", 16384, 0, NULL, NULL) = 82 <0.000009> 1435133933.896567 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 1000) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}]) <0.000015> 1435133933.899540 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}]) <0.000012> 1435133933.899639 recvfrom(3, "", 16384, 0, NULL, NULL) = 0 <0.000038> 1435133933.899735 time([1435133933]) = 1435133933 <0.000046> 1435133933.899828 close(3) = 0 <0.000031> Actual result: -------------- 1435133933.899925 write(1, "Run 13055\n", 10Run 13055) = 10 <0.000015> 1435133933.901036 time([1435133933]) = 1435133933 <0.000008> 1435133933.901104 write(1, "[NETWORK] HTTP request failed: Timeout was reached - errno: 28 ", 72[NETWORK] HTTP request failed: Timeout was reached - errno: 28 ) = 72 <0.000013> 1435133933.901199 close(2) = 0 <0.000006> 1435133933.901235 close(1) = 0 <0.000012> ------------------------------------------------------------------------ -- Edit this bug report at https://bugs.php.net/bug.php?id=69917&edit=1