Skip to content
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.

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

Guzzle Pool promise finishes before all requests are complete #2534

Closed
williamjulianvicary opened this issue Jan 2, 2020 · 20 comments
Closed

Comments

@williamjulianvicary
Copy link
Contributor

williamjulianvicary commented Jan 2, 2020

Guzzle version(s) affected: 6.5.2
PHP version: 7.3.9-1+ubuntu18.04.1+deb.sury.org+1
cURL version: 7.58.0

Description
I'm seeing an intermittent issue (frequent enough - the below may need to be ran a handful of times to see the problem) where, it appears that the Pool is finishing prematurely and the ->wait() method call is unwrapping the most recent exception - even though there may be many other requests waiting to be processed.

I've pasted a sample simple Laravel command below, which requests 100 URLs that all return a 999 response code (something that the assertions fail in the Response generation). This sometimes runs with no issue, but often (say 1 in 4 times) the call to ->wait() bubbles an exception before all other requests are finished.

How to reproduce


namespace App\Console\Commands;

use GuzzleHttp\Client;
use GuzzleHttp\Pool;
use GuzzleHttp\Psr7\Request;
use GuzzleHttp\Psr7\Response;
use GuzzleHttp\TransferStats;
use Illuminate\Console\Command;
use Log;

class TestCommand extends Command
{
    /**
     * The name and signature of the console command.
     *
     * @var string
     */
    protected $signature = 'test';

    /**
     * The console command description.
     *
     * @var string
     */
    protected $description = 'Command description';
    /**
     * @var \Closure
     */
    private $successCallback;
    /**
     * @var \Closure
     */
    private $failureCallback;

    /**
     * Create a new command instance.
     *
     * @return void
     */
    public function __construct()
    {
        parent::__construct();
        $this->failureCallback = function($reason, $index) {
            var_dump($reason->getMessage());
        };

        $this->successCallback = function ($response, $index) {
        };
    }

    public function getRequests()
    {
        for ($i=0; $i < 100; $i++) {
            yield new Request('get', 'https://httpstat.us/999');
        }
    }

    /**
     * Execute the console command.
     *
     * @return mixed
     */
    public function handle()
    {
        $client = new Client(['timeout' => 10, 'verify' => false]);

        $pool = new Pool($client, $this->getRequests(), [
            'concurrency' => '5',
            'fulfilled' => function(Response $response, $index) {
                call_user_func($this->successCallback, $response, $index);
            },
            'rejected' => function($reason, $index) {
                call_user_func($this->failureCallback, $reason, $index);
            }
        ]);

        $promise = $pool->promise();

        $promise->wait();
    }
}

Additional context
Sometimes this does not happen and the full Pool works properly, however I am still seeing some odd failure reasons:

string(57) "Status code must be an integer value between 1xx and 5xx."
string(57) "Status code must be an integer value between 1xx and 5xx."
string(93) "cURL error 23: Failed writing header (see https://curl.haxx.se/libcurl/c/libcurl-errors.html)"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
[...]

An example failure log:

$ php artisan test -v
string(57) "Status code must be an integer value between 1xx and 5xx."
string(93) "cURL error 23: Failed writing header (see https://curl.haxx.se/libcurl/c/libcurl-errors.html)"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(45) "Cannot change a rejected promise to fulfilled"
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(45) "Cannot change a rejected promise to fulfilled"
string(57) "Status code must be an integer value between 1xx and 5xx."

   InvalidArgumentException  : Status code must be an integer value between 1xx and 5xx.

  at /home/vagrant/code/tool/vendor/guzzlehttp/psr7/src/Response.php:151
    147| 
    148|     private function assertStatusCodeRange($statusCode)
    149|     {
    150|         if ($statusCode < 100 || $statusCode >= 600) {
  > 151|             throw new \InvalidArgumentException('Status code must be an integer value between 1xx and 5xx.');
    152|         }
    153|     }
    154| }
    155| 

  Exception trace:

  1   GuzzleHttp\Psr7\Response::assertStatusCodeRange()
      /home/vagrant/code/tool/vendor/guzzlehttp/psr7/src/Response.php:98

  2   GuzzleHttp\Psr7\Response::__construct(Object(GuzzleHttp\Psr7\Stream), "1.1", "999 Unknown Code")
      /home/vagrant/code/tool/vendor/guzzlehttp/guzzle/src/Handler/EasyHandle.php:81

  3   GuzzleHttp\Handler\EasyHandle::createResponse()
      /home/vagrant/code/tool/vendor/guzzlehttp/guzzle/src/Handler/CurlFactory.php:565

  4   GuzzleHttp\Handler\CurlFactory::GuzzleHttp\Handler\{closure}("
")
      [internal]:0

  5   curl_multi_exec()
      /home/vagrant/code/tool/vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php:128

  6   GuzzleHttp\Handler\CurlMultiHandler::tick()
      /home/vagrant/code/tool/vendor/guzzlehttp/guzzle/src/Handler/CurlMultiHandler.php:145

  7   GuzzleHttp\Handler\CurlMultiHandler::execute()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:246

  8   GuzzleHttp\Promise\Promise::invokeWaitFn()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:223

  9   GuzzleHttp\Promise\Promise::waitIfPending()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:267

  10  GuzzleHttp\Promise\Promise::invokeWaitList()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:225

  11  GuzzleHttp\Promise\Promise::waitIfPending()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:62

  12  GuzzleHttp\Promise\Promise::wait()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/EachPromise.php:101

  13  GuzzleHttp\Promise\EachPromise::GuzzleHttp\Promise\{closure}()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:246

  14  GuzzleHttp\Promise\Promise::invokeWaitFn()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:223

  15  GuzzleHttp\Promise\Promise::waitIfPending()
      /home/vagrant/code/tool/vendor/guzzlehttp/promises/src/Promise.php:62

  16  GuzzleHttp\Promise\Promise::wait()
      /home/vagrant/code/tool/app/Console/Commands/TestCommand.php:81

  17  App\Console\Commands\TestCommand::handle()
      /home/vagrant/code/tool/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:32


@williamjulianvicary
Copy link
Contributor Author

To add, in case it helps, this is the case if I pass a generator or an array.

Also, I don't believe "leaking" is actually correct looking into it a little further and I don't believe this is conflicting with Laravel's error handling, it seems the unwrapping on the $promise->wait() is causing the exception to bubble, however I was unable to find the race condition (presumably?) that is the issue in the first place.

@gmponos
Copy link
Member

gmponos commented Jan 2, 2020

where exceptions appear to be leaking to the main error handler rather than being caught and sent to a failure callback during a Pool request

I am failing to understand what the problem is.. Out the failure log I see that everything reached to failure callback and the exception is throw as it is supposed to be thrown... what do I miss?

@GrahamCampbell
Copy link
Member

I think the problem is that it is only "intermittent"?

@williamjulianvicary
Copy link
Contributor Author

After digging into the promise code some more, as far as I can tell the final exception leaking is ‘working as intended’? However, I could try/catch that and it would not be a problem - it doesn’t always bubble though.

My core issue is that these exceptions are bubbled before all requests are complete. In the example error above I have not trimmed the log - that should be 100 failures not 19. Sometimes this executes all 100 requests, sometimes just a handful and occasionally just a single request is made before the exception bubbles from the wait call.

I’m attempting to make requests for thousands of URLs via a generator, however intermittently this is failing and stopping further execution.

@williamjulianvicary williamjulianvicary changed the title Guzzle seems to be leaking exceptions to the main exception handler Guzzle Pool promise finishes before all requests are complete Jan 2, 2020
@williamjulianvicary
Copy link
Contributor Author

I've edited the issue name/description slightly to be less misleading with the messaging - this doesn't appear to be an exception "leak" (as this is exactly how the ->wait() is meant to respond) it instead appears to be a problem with the Pool/EachPromise/Promise iteration where intermittently the Pool finishes without completing all requests.

@williamjulianvicary
Copy link
Contributor Author

Were you able to reproduce this @GrahamCampbell / @gmponos or do I have an issue with the implementation/my stack?

@Skullbock
Copy link

Hi, sorry to jump in, but i found this issue while trying to debug this one:

spatie/crawler#271

Which depends on this exact issue.
After a bit of research, i experienced the same problem as @williamjulianvicary
Could the solution be for the Pool to intercept the \InvalidArgumentException from the Response class and "bubble it up" after the pool has finished running, maybe with a dedicated exception?

And thanks for this awesome library ;)

@williamjulianvicary
Copy link
Contributor Author

williamjulianvicary commented Feb 10, 2020

I've spent a couple hours this evening attempting to debug this.

In Promise::invokeWaitFn() we're hitting the point where an exception is thrown rather than the promise rejected.

I've added a (super simple) debug output, for when the script hits this mark, and rather than throwing the exception I've returned.

    {
        try {
            $wfn = $this->waitFn;
            $this->waitFn = null;
            $wfn(true);
        } catch (\Exception $reason) {
            if ($this->state === self::PENDING) {
                // The promise has not been resolved yet, so reject the promise
                // with the exception.
                $this->reject($reason);
            } else {
                print "here";
                return;
                // The promise was already resolved, so there's a problem in
                // the application.
                throw $reason;
            }
        }
    }

This then successfully outputs (see on line 4, this would have thrown an exception rather than reject the promise!):

string(26) "Successes: 0 | Failures: 1"
string(57) "Status code must be an integer value between 1xx and 5xx."
string(26) "Successes: 0 | Failures: 2"
herestring(57) "Status code must be an integer value between 1xx and 5xx."
string(26) "Successes: 0 | Failures: 3"
string(45) "Cannot change a rejected promise to fulfilled"
string(26) "Successes: 0 | Failures: 4"
string(45) "Cannot change a rejected promise to fulfilled"
string(26) "Successes: 0 | Failures: 5"
string(45) "Cannot change a rejected promise to fulfilled"
string(26) "Successes: 0 | Failures: 6"

I'm also seeing a lot of "Cannot change a rejected promise to fulfilled" which I believe is the underlying issue here and is causing the parent exception to leak.

@williamjulianvicary
Copy link
Contributor Author

After a little more digging around, it seems that this line is attempting to fulfil an already rejected promise:
https://github.com/guzzle/guzzle/blob/master/src/Handler/CurlMultiHandler.php#L197

This appears to be because the CurlFactory::finish method handles when curl failed, by sending a rejection as a value to fulfilled, however because the Response object now asserts (and throws an exception) that the status code is an integer and within a valid range it fails. Related Pull Request from PSR7 here: guzzle/psr7#250

If I remove those assertions my code works as intended every time:

string(97) "Unsuccessful request: `GET https://httpstat.us/999` resulted in a `999 999 Unknown Code` response"
string(28) "Successes: 98 | Failures: 98"
string(28) "Successes: 99 | Failures: 98"
string(97) "Unsuccessful request: `GET https://httpstat.us/999` resulted in a `999 999 Unknown Code` response"
string(28) "Successes: 99 | Failures: 99"
string(29) "Successes: 100 | Failures: 99"
string(97) "Unsuccessful request: `GET https://httpstat.us/999` resulted in a `999 999 Unknown Code` response"
string(30) "Successes: 100 | Failures: 100"

In short, I'm not sure on the resolution of this issue, but I now believe I understand the root cause:

  • The CurlHandler class is always fulfilling the promise, even if that promise has already been rejected due to an exception elsewhere in the stack, this is a breaking problem.
  • This will be commonly ran into when a status code range is out of the bounds of the assertions within the PSR7 response object - following changes here: Assert values according to PSR standard psr7#250 (but any exception, anywhere within the guzzle stack will cause this)
  • There is a race condition somewhere, that causes the exceptions to stop execution flow. I suspect this is where a Curl request fulfils before the exception has had a chance to bubble. Causing a fulfilled promise to attempt to be rejected - which causes the application error on the promise.

Note, this problem is worse than I first thought as well, as soon as any promise fulfils then rejects, all further promises are rejecting. Rolling back my changes to the base causes ~5 of the 95 200 OK responses to reject which is a serious issue for anyone using the pool in cases where they may run into these assertions in the PSR7 library!

@williamjulianvicary
Copy link
Contributor Author

williamjulianvicary commented Feb 10, 2020

Final message before I stop debugging for the evening. This boils down to the build of the Response object, called within the closure here:

$easy->createResponse();

As this build fails, it's causing some kind of catastrophic failure within Curl Multi, probably because an exception is being raised but this isn't actually halting execution due to the way that promises (usually) stop exceptions from bubbling up. As this is an exception that occurs during the header execution I feel this should be caught and the exception return a "error handling headers" exception - but that's not entirely user friendly.

One option, which I'm not sure I'm happy with, would be to do as follows:

Change EasyHandle to pre-validate the status code and give it a number that is not a valid status code, but within the assertion range:

        $statusCode = intval($startLine[1]);
        $statusCode = (100 > $statusCode || $statusCode > 600) ? 599 : $statusCode;

        // Attach a response to the easy handle with the parsed headers.
        $this->response = new Response(
            $statusCode,
            $headers,
            $this->sink,
            substr($startLine[0], 5),
            isset($startLine[2]) ? (string) $startLine[2] : null
        );

Add a try/catch for any other errors within the closure which creates the response:

try {
                    $easy->createResponse();
                } catch (\Exception $e) {
                    return -1;
                }

Anyone else have any bright ideas? This is seriously blocking for any sort of web crawling where you cannot expect a valid status code in advance and EasyHandle is not (ironically) easy to override.

Alternatively, don't use the PSR7 Response object within Guzzle - again, not ideal but I'm struggling to find an alternative.

@trevorgehman
Copy link

Just chiming in. I suspect we may be experiencing this issue with our Guzzle pool, but it's difficult to debug. We have "missing" requests, which I can only trace to the promise finishing before the responses have been passed to the callback functions.

@websitevirtuoso
Copy link

Sad I have the problem with this issue as well

@tomdickman
Copy link

Has there been any traction on this? Any sort of crawling I do is currently completely broken with Guzzle, mostly due to LinkedIn responses which return a 999 status code when crawling unless UA and IP address is white listed.

@williamjulianvicary
Copy link
Contributor Author

I know it’s not ideal but the referenced pull request could be used instead, I’m keeping that branch open so if you alias your composer file to it, it’ll temporarily fix the bugs you’re experiencing :-) #2591

@strarsis
Copy link

Composer-based patch: spatie/crawler#271 (comment)
However, I had trouble applying that patch to my project.

@williamjulianvicary
Copy link
Contributor Author

PR has been merged - to be released in 7.2 release.

@kdefives
Copy link

Hello guys and @williamjulianvicary ,

I still have the same error:

request.CRITICAL: Uncaught PHP Exception GuzzleHttp\Promise\RejectionException: "The promise was rejected with reason: Inv
oking the wait callback did not resolve the promise" at /var/www/vendor/guzzlehttp/promises/src/Create.php line 62 {"exception":"[object] (GuzzleHttp\\Promis
e\\RejectionException(code: 0): The promise was rejected with reason: Invoking the wait callback did not resolve the promise at /var/www/vendor/guzzlehttp/pr
omises/src/Create.php:62)"} []

Part of stacktrace:

GuzzleHttp\Promise\RejectionException:
The promise was rejected with reason: Invoking the wait callback did not resolve the promise

  at vendor/guzzlehttp/promises/src/Create.php:62
  at GuzzleHttp\Promise\Create::exceptionFor('Invoking the wait callback did not resolve the promise')
     (vendor/guzzlehttp/promises/src/Promise.php:72)
  at GuzzleHttp\Promise\Promise->wait()

Using version:

root@7a917597f9c1:/var/www# composer show | grep guzzle
guzzlehttp/guzzle                     7.2.0     Guzzle is a PHP HTTP client library
guzzlehttp/promises                   1.4.0     Guzzle promises library
guzzlehttp/psr7                       1.7.0     PSR-7 message implementation that also provides common utility methods
kevinrob/guzzle-cache-middleware      v3.3.1    A HTTP/1.1 Cache for Guzzle 6. It's a simple Middleware to be added in the HandlerStack. (RFC 7234)
spatie/guzzle-rate-limiter-middleware 2.0.0     A rate limiter for Guzzle

My code where i have the issue:

public function isValidProductIds(array $productIdsToCheck): array
    {
        $notValidProductIds = array();

        // Get http headers (api token)
        $httpHeaders = $this->getHttpHeaders();

        // Create request function
        $requests = function ($productIdsToCheck, $httpHeaders)
        {
            foreach ($productIdsToCheck as $productId)
            {
                $url = sprintf('article/%d', $productId);
                yield new Request(
                    'GET',
                    $url,
                    $httpHeaders
                );
            }
        };

        // Create the pool 
        $pool = new Pool($this->httpClient, $requests($productIdsToCheck, $httpHeaders), [
            'concurrency' => 5,
            'fulfilled' => function (Response $response, $index)
            {
                // this is delivered each successful response
                $this->logger->debug('OK for index '.$index.' : HTTP CODE '.$response->getStatusCode());
            },
            'rejected' => function (RequestException $reason, $index) use (&$notValidProductIds, $productIdsToCheck)
            {
                $notValidProductIds[] = $productIdsToCheck[$index];
                $this->logger->info('GET index '.$index.' to check productId failed: '.$reason->getMessage());
            },
        ]);

        // Initiate the transfers and create a promise
        $promise = $pool->promise();

        // Force the pool of requests to complete.
        $promise->wait();

        return $notValidProductIds;
    }

Note: I do not know if it could help you or not to investigate but seems the error appears only when they are a lot of 'rejected' (ie. 404 not found).

Tell me if you need more infos.

Regards

@williamjulianvicary
Copy link
Contributor Author

I think this is different, unless they aren't 404 errors?

The issue that was resolved with the pull request was related to the header function throwing an exception that was not caught (which threw CURL into an odd state). A 404 status response would not hit that workflow so I think is unrelated to the fix that was deployed.

I'm happy to look into this if you can simplify the code into a reproducible example with an endpoint that is publicly accessible (such as with https://httpbin.org/ as URLs?)

@kdefives
Copy link

kdefives commented Nov 16, 2020

Update : I tested different type of cache (flysystem, doctrinecache and psr6) with GreedyCacheStrategy. Same issue for both. I cannot test with PrivateCacheStrategy because i my use case the cache do not cache correctly with that strategy. But it seems to confirm that the problem appears only when the cache is used.

@williamjulianvicary , you can reproduce the error by doing this steps below. Hope this will help you to troubleshoot. For info i am using Symfony 5.1.8.

Step 1:
Let's execute this code

private function test(){

        $productIdsToCheck = new ArrayCollection([1,2,3,4,100,6,7,8,9,99]);

        // Create request function
        $requests = function ($productIdsToCheck)
        {
            foreach ($productIdsToCheck as $key => $productId)
            {
                yield new Request(
                    'GET',
                    'https://httpbin.org/'.$productId
                );
            }
        };

        // Create the pool using $request function
        $pool = new Pool($this->httpClient, $requests($productIdsToCheck), [
            'concurrency' => 5,
            'fulfilled' => function (Response $response, $index)
            {
                // this is delivered each successful response
            },
            'rejected' => function (RequestException $reason, $index)
            {
            },
        ]);

        // Initiate the transfers and create a promise
        $promise = $pool->promise();

        // Force the pool of requests to complete.
        $promise->wait();
    }

Everything is ok the first time.

Step 2:
Now, just change the value from 100 to 10 into the ArrayCollection $productIdsToCheck variable and re-execute the same code

private function test(){

        $productIdsToCheck = new ArrayCollection([1,2,3,4,10,6,7,8,9,99]);

        // Create request function
        $requests = function ($productIdsToCheck)
        {
            foreach ($productIdsToCheck as $key => $productId)
            {
                yield new Request(
                    'GET',
                    'https://httpbin.org/'.$productId
                );
            }
        };

        // Create the pool using $request function
        $pool = new Pool($this->httpClient, $requests($productIdsToCheck), [
            'concurrency' => 5,
            'fulfilled' => function (Response $response, $index)
            {
                // this is delivered each successful response
            },
            'rejected' => function (RequestException $reason, $index)
            {
            },
        ]);

        // Initiate the transfers and create a promise
        $promise = $pool->promise();

        // Force the pool of requests to complete.
        $promise->wait();
    }

And the error message appears:

The promise was rejected with reason: Invoking the wait callback did not resolve the promise

Important:
Here how my $httpClient is setted (using dependency injection as i am using symfony 5.1.8):

#services.yaml

services:
_defaults:
        autowire: true      # Automatically injects dependencies in your services.
        autoconfigure: true # Automatically registers your services as commands, event subscribers, etc.
        bind:
            $httpClient: '@http_api_client'

        Kevinrob\GuzzleCache\Storage\Psr6CacheStorage:
                class: Kevinrob\GuzzleCache\Storage\Psr6CacheStorage
                arguments: [ '@cache.app' ]

            Kevinrob\GuzzleCache\Strategy\GreedyCacheStrategy:
                class: Kevinrob\GuzzleCache\Strategy\GreedyCacheStrategy
                arguments: [ '@Kevinrob\GuzzleCache\Storage\Psr6CacheStorage', '3600' ]

            Kevinrob\GuzzleCache\CacheMiddleware:
                class: Kevinrob\GuzzleCache\CacheMiddleware
                arguments: [ '@Kevinrob\GuzzleCache\Strategy\GreedyCacheStrategy' ]

        GuzzleHttp\HandlerStack:
                class: GuzzleHttp\HandlerStack
                factory: [ 'GuzzleHttp\HandlerStack', create ]
                calls:
                    - [ push, [ '@log_middleware', 'log' ] ]
                    - [ push, [ '@Kevinrob\GuzzleCache\CacheMiddleware', 'cache' ] ]
                    - [ push, [ '@Spatie\GuzzleRateLimiterMiddleware\RateLimiterMiddleware', 'rate-limit' ] ]

        http_api_client_
                class: GuzzleHttp\Client
                arguments:
                    - handler: '@GuzzleHttp\HandlerStack'

Important 2:
If i remove the cache feature by commenting the line - [ push, [ '@Kevinrob\GuzzleCache\CacheMiddleware', 'cache' ] ] , then everything woks fine.
If you re-enable cache feature, the problem appears again. Seems linked to the cache. 🤔

Tell me if you think it is better to open a new issue.

@kdefives
Copy link

Issue created as it seems not linked to the current issue : #2822

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants