From: maxence at typhon dot com
Operating system: Debian 7
PHP version: 5.6.10
Package: cURL related
Bug Type: Bug
Bug description:curl_exec sometimes raise timeout error without even trying a connect() before
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 bug report at https://bugs.php.net/bug.php?id=69917&edit=1
--
Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=69917&r=trysnapshot54
Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=69917&r=trysnapshot55
Try a snapshot (trunk): https://bugs.php.net/fix.php?id=69917&r=trysnapshottrunk
Fixed in SVN: https://bugs.php.net/fix.php?id=69917&r=fixed
Fixed in release: https://bugs.php.net/fix.php?id=69917&r=alreadyfixed
Need backtrace: https://bugs.php.net/fix.php?id=69917&r=needtrace
Need Reproduce Script: https://bugs.php.net/fix.php?id=69917&r=needscript
Try newer version: https://bugs.php.net/fix.php?id=69917&r=oldversion
Not developer issue: https://bugs.php.net/fix.php?id=69917&r=support
Expected behavior: https://bugs.php.net/fix.php?id=69917&r=notwrong
Not enough info: https://bugs.php.net/fix.php?id=69917&r=notenoughinfo
Submitted twice: https://bugs.php.net/fix.php?id=69917&r=submittedtwice
register_globals: https://bugs.php.net/fix.php?id=69917&r=globals
PHP 4 support discontinued: https://bugs.php.net/fix.php?id=69917&r=php4
Daylight Savings: https://bugs.php.net/fix.php?id=69917&r=dst
IIS Stability: https://bugs.php.net/fix.php?id=69917&r=isapi
Install GNU Sed: https://bugs.php.net/fix.php?id=69917&r=gnused
Floating point limitations: https://bugs.php.net/fix.php?id=69917&r=float
No Zend Extensions: https://bugs.php.net/fix.php?id=69917&r=nozend
MySQL Configuration Error: https://bugs.php.net/fix.php?id=69917&r=mysqlcfg