Unexpected TimedoutException ?

sandrokeil commented 7 years ago

Consider this connection

$connection = new UnixDomainSocket(
    'unix:///var/run/php7-fpm.sock',  # Socket path to php-fpm
    5000,                                   # Connect timeout in milliseconds (default: 5000)
    5000,                                   # Read/write timeout in milliseconds (default: 5000)
    true,                                  # Make socket connection persistent (default: false)
    true                                   # Keep socket connection alive (default: false)
);

If I start 5 async requests where the script sleeps for 1 second all is fine with the configuration above. If I increase the sleep to 2 seconds, I got a TimedoutException. As far as I can see, the timeout should be for each waitForResponse independently right?

hollodotme commented 7 years ago

@sandrokeil I can't reproduce the issue you describe.

I did the following (on current development branch with request / response objects):

Setting read/write timeout to 2000 milliseconds (2 seconds)
Sending 20 async requests and collecting all request IDs
Each request sleeps for ($i x 0.1) seconds (So 20th will sleep 2 seconds)
looping over the 20 request IDs and calling waitForResponse()
as expected the 20th response failed with TimedoutException

daemon.php

<?php declare(strict_types = 1);

use hollodotme\FastCGI\Client;
use hollodotme\FastCGI\Requests\PostRequest;
use hollodotme\FastCGI\SocketConnections\UnixDomainSocket;

require __DIR__ . '/vendor/autoload.php';

$connection = new UnixDomainSocket(
    'unix:///var/run/php/php7.1-fpm.sock',  # Socket path to php-fpm
    5000,                                   # Connect timeout in milliseconds (default: 5000)
    2000,                                   # Read/write timeout in milliseconds (default: 5000)
    true,                                   # Make socket connection persistent (default: false)
    false                                   # Keep socket connection alive (default: false)
);

$client  = new Client( $connection );
$request = new PostRequest( '/vagrant/worker.php', '' );

$calls      = $argv[1] ?? 1;
$requestIds = [];

for ( $i = 0; $i < $calls; $i++ )
{
    $request->setContent( http_build_query( [ 'sleep' => $i + 1 ] ) );

    $requestId = $client->sendAsyncRequest( $request );
    echo "Sent request with ID {$requestId} asynchronously...\n";
    $requestIds[] = $requestId;
}

echo "\nRetrieving responses..\n\n";

foreach ( $requestIds as $index => $requestId )
{
    $response = $client->waitForResponse( $requestId );
    echo ($index+1) . ". ID {$requestId}: {$response->getBody()}\n";
}

worker.php

<?php declare(strict_types = 1);

$usleep  = (int)$_POST['sleep'] * 1000 * 100;
$seconds = $usleep / 1000 / 1000;

echo "Sleeping {$seconds} seconds...";

usleep( $usleep );

Execution results:

Sent request with ID 57104 asynchronously...
Sent request with ID 60771 asynchronously...
Sent request with ID 36847 asynchronously...
Sent request with ID 57566 asynchronously...
Sent request with ID 7294 asynchronously...
Sent request with ID 39925 asynchronously...
Sent request with ID 50079 asynchronously...
Sent request with ID 30835 asynchronously...
Sent request with ID 36462 asynchronously...
Sent request with ID 56332 asynchronously...
Sent request with ID 45694 asynchronously...
Sent request with ID 31252 asynchronously...
Sent request with ID 47607 asynchronously...
Sent request with ID 489 asynchronously...
Sent request with ID 39954 asynchronously...
Sent request with ID 48723 asynchronously...
Sent request with ID 28123 asynchronously...
Sent request with ID 49895 asynchronously...
Sent request with ID 26486 asynchronously...
Sent request with ID 22025 asynchronously...

Retrieving responses..

1. ID 57104: Sleeping 0.1 seconds...
2. ID 60771: Sleeping 0.2 seconds...
3. ID 36847: Sleeping 0.3 seconds...
4. ID 57566: Sleeping 0.4 seconds...
5. ID 7294: Sleeping 0.5 seconds...
6. ID 39925: Sleeping 0.6 seconds...
7. ID 50079: Sleeping 0.7 seconds...
8. ID 30835: Sleeping 0.8 seconds...
9. ID 36462: Sleeping 0.9 seconds...
10. ID 56332: Sleeping 1 seconds...
11. ID 45694: Sleeping 1.1 seconds...
12. ID 31252: Sleeping 1.2 seconds...
13. ID 47607: Sleeping 1.3 seconds...
14. ID 489: Sleeping 1.4 seconds...
15. ID 39954: Sleeping 1.5 seconds...
16. ID 48723: Sleeping 1.6 seconds...
17. ID 28123: Sleeping 1.7 seconds...
18. ID 49895: Sleeping 1.8 seconds...
19. ID 26486: Sleeping 1.9 seconds...
PHP Fatal error:  Uncaught hollodotme\FastCGI\Exceptions\TimedoutException: Timed out in /vagrant/vendor/hollodotme/fast-cgi-client/src/Client.php:361
Stack trace:
#0 /vagrant/daemon.php(36): hollodotme\FastCGI\Client->waitForResponse(22025)
#1 {main}
  thrown in /vagrant/vendor/hollodotme/fast-cgi-client/src/Client.php on line 361

Fatal error: Uncaught hollodotme\FastCGI\Exceptions\TimedoutException: Timed out in /vagrant/vendor/hollodotme/fast-cgi-client/src/Client.php on line 361

hollodotme\FastCGI\Exceptions\TimedoutException: Timed out in /vagrant/vendor/hollodotme/fast-cgi-client/src/Client.php on line 361

Call Stack:
    0.0007     354688   1. {main}() /vagrant/daemon.php:0
   19.0339     570208   2. hollodotme\FastCGI\Client->waitForResponse() /vagrant/daemon.php:36

sandrokeil commented 7 years ago

If you use in your example $requestId = $client->sendAsyncRequest( $request, 6000 ); then the TimedoutException should never appear, even if you use 40 async requests.

I've tested it with version 2.1.0. And it works now. I guess the TimedoutException occurs if not enough PHP-FPM children are available to process the requests.

hollodotme / fast-cgi-client

Unexpected TimedoutException ? #4