compress and connecttimeout interfere with low_speed_limit

[rcanavan]

Given the following, intentionally slow test data generator:

<?php
print(str_repeat("a", 700000)."\n");
usleep(500000);
foreach (str_split("bcdef") as $i) {
    print(str_repeat($i, 300000)."\n");
    sleep(1);
}

The test program below waits until the transfer is finished (5.5s) or the 9s timeout has occurred before stating that Operation too slow. Less than 100000000 bytes/sec transferred the last 2 seconds. If the transfer does not finish before the timeout, the error message is 'Operation timed out after'. if compress is false or connecttimeout is not set, the program terminates in 2-3s.

<?php
$c = new http\Client;
$r = new http\Client\Request("GET", "http://localhost:14080/slow.php");
$r->setOptions(array (
'compress' => TRUE,
'low_speed_time' => 2,
'low_speed_limit' => 100000000,
'timeout' => 9,
'connecttimeout' => 7));
try {
    $c->enqueue($r)->send();
} catch (Exception $e) {
    echo $e;
}
unset($r, $client);

A roughly equivalent program using the builtin PHP curl extension terminates in just over 2s:

<?php

$ch = curl_init();
curl_setopt($ch, CURLOPT_URL, 'http://localhost:14080/slow.php');
curl_setopt($ch, CURLOPT_LOW_SPEED_LIMIT, 100000000);
curl_setopt($ch, CURLOPT_LOW_SPEED_TIME, 2);
curl_setopt($ch, CURLOPT_TIMEOUT, 9);
curl_setopt($ch, CURLOPT_CONNECTTIMEOUT, 9);
curl_setopt($ch, CURLOPT_ENCODING, 'gzip,deflate');
$response = curl_exec($ch);

var_export($response);
var_export(curl_getinfo($ch));
print("\ncurl error: ".curl_error($ch)."\n");
curl_close($ch);

[m6w6]

Works for me(tm).

$ time php curl_slow.php
falsearray (
  'url' => 'http://localhost/tests/slow.php',
  'content_type' => 'text/html; charset=UTF-8',
  'http_code' => 200,
  'header_size' => 212,
  'request_size' => 93,
  'filetime' => -1,
  'ssl_verify_result' => 0,
  'redirect_count' => 0,
  'total_time' => 2.0055930000000002,
  'namelookup_time' => 0.0042900000000000004,
  'connect_time' => 0.0044669999999999996,
  'pretransfer_time' => 0.0045259999999999996,
  'size_upload' => 0.0,
  'size_download' => 1300003.0,
  'speed_download' => 648188.0,
  'speed_upload' => 0.0,
  'download_content_length' => -1.0,
  'upload_content_length' => -1.0,
  'starttransfer_time' => 0.0051500000000000001,
  'redirect_time' => 0.0,
  'redirect_url' => '',
  'primary_ip' => '127.0.0.1',
  'certinfo' => 
  array (
  ),
  'primary_port' => 80,
  'local_ip' => '127.0.0.1',
  'local_port' => 34028,
)
curl error: Operation too slow. Less than 100000000 bytes/sec transferred the last 2 seconds
php curl_slow.php  0.02s user 0.02s system 1% cpu 2.044 total

$ time php http_slow.php
http\Exception\RuntimeException: http\Client::send(): Timeout was reached; Operation too slow. Less than 100000000 bytes/sec transferred the last 2 seconds (http://localhost/tests/slow.php) in /tmp/http_slow.php:11
Stack trace:
#0 /tmp/http_slow.php(11): http\Client->send()
#1 {main}php http_slow.php  0.01s user 0.03s system 1% cpu 2.037 total

[alex-schneider]

On my (Ubuntu 16.04 / PHP 7.1.3) system I get (reproducible):

"connecttimeout" is set to 7:

• compress=true => real 0m5.529s
• compress=false => real 0m2.027s

"connecttimeout" is not set:

• compress=true => real 0m3.036s
• compress=false => real 0m2.032s

The exception message is always the same:

• Timeout was reached; Operation too slow. Less than 100000000 bytes/sec transferred the last 2 seconds...

curl 7.47.0 (x86_64-pc-linux-gnu) libcurl/7.47.0 GnuTLS/3.4.10 zlib/1.2.8 libidn/1.32 librtmp/2.3

[rcanavan]

I can't reproduce this myself at the moment, but I've found the output of strace of one run in my terminal history. It shows that a select call isn't returning in time:

     0.000003 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000019 socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 3
     0.000028 fcntl(3, F_GETFL)         = 0x2 (flags O_RDWR)
     0.000014 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
     0.000013 connect(3, {sa_family=AF_INET6, sin6_port=htons(14080), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
     0.000060 poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=3, revents=POLLOUT|POLLWRNORM}])
     0.000019 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
     0.000016 getpeername(3, {sa_family=AF_INET6, sin6_port=htons(14080), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
     0.000015 getsockname(3, {sa_family=AF_INET6, sin6_port=htons(55196), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
     0.000034 sendto(3, "GET /slow.php HTTP/1.1\r\nHost: lo"..., 148, MSG_NOSIGNAL, NULL, 0) = 148
     0.000049 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
     0.000020 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000017 select(4, [3], [], [], {0, 1000}) = 0 (Timeout)
     0.001105 rt_sigaction(SIGPIPE, NULL, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, 8) = 0
     0.000021 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000015 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
     0.000025 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000018 select(4, [3], [], [], {0, 198000}) = 0 (Timeout)
     0.198414 rt_sigaction(SIGPIPE, NULL, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, 8) = 0
     0.000055 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000047 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
     0.000060 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000029 select(4, [3], [], [], {0, 1000}) = 0 (Timeout)
     0.001099 rt_sigaction(SIGPIPE, NULL, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, 8) = 0
     0.000025 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000025 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
     0.000033 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000026 select(4, [3], [], [], {6, 791000}) = 1 (in [3], left {1, 487561})
     5.303506 rt_sigaction(SIGPIPE, NULL, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, 8) = 0
     0.000149 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f542c080860}, NULL, 8) = 0
     0.000028 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}])
     0.000027 recvfrom(3, "HTTP/1.1 200 OK\r\nDate: Fri, 24 M"..., 16384, 0, NULL, NULL) = 2348
     0.000059 brk(0x55cf0d6fa000)       = 0x55cf0d6fa000

[rcanavan]

Since I can't currently reproduce this myself, I can't verify it, but it's likely that the server that serves the slow.php test script must gzip-encode the output of the script.

[m6w6]

I still get the correct error. Note that the default for connecttimeout is 3.

My guess would be, that the server's gzip layer buffers your response.

[rcanavan]

You're probably right. The behaviour of low_speed_time depends heavily on when partially filled output buffers are finally flushed to the client. It turns out that curl_multi_timeout() is wonky and regularly suggests timeouts that only really cater for CURLOPT_TIMEOUT, but not CURLOPT_LOW_SPEED_TIME. Even the curl example source code appears to use workaround for this (in docs/examples/multi-app.c) in that it sets an upper limit of 1s for the select timeout. The patch below would do the same for ext-http

diff -ur src/php_http_client_curl.h src/php_http_client_curl.h
--- src/php_http_client_curl.h  2016-11-11 12:27:06.250682897 +0100
+++ src/php_http_client_curl.h  2017-04-07 16:21:22.058879223 +0200
@@ -43,9 +43,13 @@

 static inline void php_http_client_curl_get_timeout(php_http_client_curl_t *curl, long max_tout, struct timeval *timeout)
 {
-   if ((CURLM_OK == curl_multi_timeout(curl->handle->multi, &max_tout)) && (max_tout > 0)) {
+   if ((CURLM_OK == curl_multi_timeout(curl->handle->multi, &max_tout)) && (max_tout > 0) && (max_tout < 1000)) {
        timeout->tv_sec = max_tout / 1000;
        timeout->tv_usec = (max_tout % 1000) * 1000;
+   } else if (max_tout >= 1000) {
+       /* workaround curl_multi_timeout() wonkiness */
+       timeout->tv_sec = 1;
+       timeout->tv_usec = 0;
    } else {
        timeout->tv_sec = 0;
        timeout->tv_usec = 1000;

we're currently using the following 3 scripts to tests for various variants of slow timeouts:

 <?php
print(str_repeat("a", ' . 2 * $size . ')."\n");
sleep(1);
foreach (str_split("bcdefghijklmnop") as $i) {
   print(str_repeat($i, ' . ($size / 3) . ')."\n");
   sleep(1);
 }

<?php
print(str_repeat("a", ' . 2 * $size . ')."\n");
sleep(17);

<?php
sleep(17);

I honestly can't find the commit 29147ade0456a mentioned in https://curl.haxx.se/mail/lib-2017-04/0031.html, but since it's going to take years until it appears in Linux distributions, a workaround in ext-http is still required.

[m6w6]

I don't know about the sha, but I guess this fix was meant? https://github.com/curl/curl/pull/1390

This should be in 7.54

[rcanavan]

This one is also required, but it has also landed in 7.54: https://github.com/curl/curl/pull/1407

That still would not help RHEL or CentOS 7 users, since neither has been backported into their curl packages. Any chance you could merge the patch posted above or something functionally similar?

[m6w6]

Sure! Thanks, and sorry it took so long.

[rcanavan]

Thank you for following up on this issue at all.