8000 [HttpClient] Timeout or max_duration not honored · Issue #49113 · symfony/symfony · GitHub
[go: up one dir, main page]
Skip to content

[HttpClient] Timeout or max_duration not honored #49113

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
peter17 opened this issue Jan 26, 2023 · 7 comments
Closed

[HttpClient] Timeout or max_duration not honored #49113

peter17 opened this issue Jan 26, 2023 · 7 comments
Labels
Bug HttpClient Status: Needs Review

Comments

@peter17
Copy link
Contributor
peter17 commented Jan 26, 2023

Symfony version(s) affected

6.2.5

Description

I observe a regression in v6.2.5: #44544 was fixed and is now happening again.

How to reproduce

<?php

use Symfony\Component\HttpClient\HttpClient;
use Symfony\Component\HttpClient\Exception\TransportException;
use Symfony\Component\Stopwatch\Stopwatch;

require_once __DIR__.'/vendor/autoload_runtime.php';

$client = HttpClient::create();
$stopwatch = new Stopwatch();

$stopwatch->start('not parallel');
try {
    $client->request('GET', 'http://10.255.255.1', ['timeout' => 5]);
} catch (TransportException) {
    echo ".";
}
echo "\n".$stopwatch->stop('not parallel')."\n";

$stopwatch->start('parallel');
$requests = [];
for ($i = 0; $i < 10; $i++) {
    $requests[] = $client->request('GET', 'http://10.255.255.1', ['timeout' => 5]);
}
foreach ($requests as $response) {
    try {
        $response->getContent();
    } catch (TransportException) {
        echo ".";
    }
}
echo "\n".$stopwatch->stop('parallel')."\n";

The output is:

.
default/not parallel: 8.00 MiB - 5009 ms
..........
default/parallel: 8.00 MiB - 50053 ms

But the last value should be around 5 s not 50 s.

Thanks!

Possible Solution

No response

Additional Context

No response
@peter17 peter17 added the Bug label Jan 26, 2023
@peter17
Copy link
Contributor Author
peter17 commented Jan 26, 2023

My mistake: I was testing the reproducer on a PHP version without the curl extension, hence the observation. So the reproducer is invalid.

I am still investigating however, because I still have a problem of timeouts not honored on parallel requests.

I will provide more information later today. Best regards

@nicolas-grekas
Copy link
Member

The thing that changed is #48966
Try looking for Content-Length headers before and after the patch maybe, using $response->getInfo('debug') when the first chunk is received (or after getStatusCode has been called).

@peter17 peter17 changed the title [HttpClient] Not handling timeouts asynchronously (regression) [HttpClient] Timeout or max_duration not honored Jan 26, 2023
@peter17
Copy link
Contributor Author
peter17 commented Jan 26, 2023

Hi @nicolas-grekas

Here is a correct reproducer:

<?php

use Symfony\Component\HttpClient\HttpClient;
use Symfony\Component\HttpClient\Exception\TransportException;
use Symfony\Component\Stopwatch\Stopwatch;

require_once __DIR__.'/vendor/autoload_runtime.php';

$url = 'http://gittigidiyor.com/toto';
$params = ['timeout' => 5, 'max_duration' => 5];

$client = HttpClient::create();
$stopwatch = new Stopwatch();

$stopwatch->start('not parallel');
try {
    $client->request('GET', $url, $params);
} catch (TransportException) {
    echo ".";
}
echo "\n".$stopwatch->stop('not parallel')."\n";

$stopwatch->start('parallel');
$requests = [];
for ($i = 0; $i < 10; $i++) {
    $requests[] = $client->request('GET', $url, $params);
}
foreach ($requests as $response) {
    try {
        $response->getContent();
    } catch (TransportException) {
        echo ".";
    }
}
echo "\n".$stopwatch->stop('parallel')."\n";

and the output:

.
default/not parallel: 8.00 MiB - 15940 ms
..........
default/parallel: 8.00 MiB - 20954 ms

The problem is not related to parallel requests, I updated the title of the issue.

I think the observed time is related to a failure in DNS resolution, but why doesn't curl honor the timeout and/or max_duration?

Any suggestion would be greatly appreciated! Thanks!

@peter17
Copy link
Contributor Author
peter17 commented Jan 26, 2023

One more thing:

I am trying to force my request to stop after a specific time using:

            'on_progress' => function (int $dlNow, int $dlSize, array $info): void {
                $url = $info['url'];
                dump($url.' - '.$info['total_time']);
                if (($totalTime = $info['total_time']) > 5) {
                    throw new CustomTimeoutException('Abort request on '.$url.' after '.((int) $totalTime).' s');
                }
            },

And I see lines like those:

^ "http://gittigidiyor.com/toto - 185.838181"
^ "http://gittigidiyor.com/toto - 200.960239"
^ "http://gittigidiyor.com/toto - 200.961567"

How is that possible? It looks like either the CustomTimeoutException is not thrown or maybe it is but doesn't interrupt the request?

@nicolas-grekas
Copy link
Member

This now looks like a duplicate of #47246, and we can't do anything about it unfortunately.

@peter17
Copy link
Contributor Author
peter17 commented Jan 26, 2023

Thanks! Yes, thanks for pointing this, it looks like it is the same issue.

I is indeed related to curl, not to HttpClient.

Here are a few more observations which may be useful to other people encountering this issue!

TL;DR: it is fixed by curl/curl#9147

A minimal test.php (from your code on #47246):

<?php
 
$h = curl_init('http://gittigidiyor.com/toto'); 
curl_setopt_array($h, [
    CURLOPT_CONNECTTIMEOUT => 1,
    CURLOPT_TIMEOUT => 1,
]);
 
curl_exec($h);

?>

I am running the php:8.2.1-fpm Docker image. It contains this version of curl:

curl 7.74.0 (x86_64-pc-linux-gnu) libcurl/7.74.0 OpenSSL/1.1.1n zlib/1.2.11 brotli/1.0.9 libidn2/2.3.0 libpsl/0.21.0 (+libidn2/2.3.0) libssh2/1.9.0 nghttp2/1.43.0 librtmp/2.3

I obtain:

$ date ; curl -vv 'http://gittigidiyor.com/toto' --connect-timeout 1 --max-time 1 ; date
Thu Jan 26 11:48:19 CET 2023
* Resolving timed out after 1000 milliseconds
* Closing connection 0
curl: (28) Resolving timed out after 1000 milliseconds
Thu Jan 26 11:48:35 CET 2023


$ date;php test2.php;date
Thu Jan 26 11:40:54 CET 2023

Thu Jan 26 11:41:09 CET 2023

That's 15 seconds instead of 1 expected.

Now, I create the following Dockerfile:

FROM php:8.2.1-fpm-alpine

RUN apk add --update libzip-dev curl-dev &&\
    docker-php-ext-install curl && \
    apk del gcc g++ &&\
    rm -rf /var/cache/apk/*

docker build -t toto .
docker run -it toto sh

I now have:

curl 7.87.0 (x86_64-alpine-linux-musl) libcurl/7.87.0 OpenSSL/3.0.7 zlib/1.2.13 brotli/1.0.9 nghttp2/1.51.0

I obtain:

# date ; curl -vv 'http://gittigidiyor.com/toto' --connect-timeout 1 --max-time 1 ; date
Thu Jan 26 10:49:38 UTC 2023
* Resolving timed out after 1000 milliseconds
* Closing connection 0
curl: (28) Resolving timed out after 1000 milliseconds
Thu Jan 26 10:49:39 UTC 2023

1 second, as expected

# date;php test.php;date
Thu Jan 26 10:39:05 UTC 2023
Thu Jan 26 10:39:10 UTC 2023

That's 5 seconds, not 1, but it is still much better than previously!

Conclusion: update curl!

Best regards

@peter17 peter17 closed this as completed Jan 26, 2023
@nicolas-grekas
Copy link
Member

Thanks for the link to curl. I submitted php/php-src#10454 to have this accessible in php.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug HttpClient Status: Needs Review
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nicolas-grekas @peter17 @carsonbot
0